Skip Menu |

This queue is for tickets about the Slay-Maker CPAN distribution.

Report information
The Basics
Id: 28627
Status: resolved
Worked: 1 hour (60 min)
Priority: 0/
Queue: Slay-Maker

People
Owner: Nobody in particular
Requestors: ANDK [...] cpan.org
Cc:
AdminCc:

Bug Information
Severity: Important
Broken in: 0.05
Fixed in: 0.06



Subject: Random test results
I ran make test 15 times and three times it fails. It's always tests 45 and 48 failing and the output is this one: t/make....# Test 45 got: "1" (t/make.t at line 372) # Expected: "" # t/make.t line 372 is: ok( join(',',@new_stats[8,9]) eq join(',',@file_0_stats[8,9]), '' ) ; # Test 48 got: "1" (t/make.t at line 388) # Expected: "" # t/make.t line 388 is: ok( join(';',@new_stats[7..9]) eq join(';',@file_0_stats[7..9]), '' ); FAILED tests 45, 48 ^IFailed 2/60 tests, 96.67% okay Failed Test Stat Wstat Total Fail List of Failed ------------------------------------------------------------------------------- t/make.t 60 2 45 48
I sent an email to the original developer of Slay::Maker (I only updated it to get rid of pseudohashes, which are no longer supported in perl 5.9.5 and to make a few minor enhancements). Here is his response: Hmm, comments inline below, in case they help. Show quoted text
> > t/make....# Test 45 got: "1" (t/make.t at line 372) > # Expected: "" > # t/make.t line 372 is: ok( join(',',@new_stats[8,9]) eq > join(',',@file_0_stats[8,9]), '' ) ;
This is testing to see if file 0 has been re-made; it should not have been, but has been. If you can reproduce this, try removing the "eq" and replacing it with a "," in those two tests so it'll dump out the numbers on a good test and a bad test, that way we can be sure it's the mod_time and not the size that is changing. Show quoted text
> # Test 48 got: "1" (t/make.t at line 388) > # Expected: "" > # t/make.t line 388 is: ok( join(';',@new_stats[7..9]) eq > join(';',@file_0_stats[7..9]), '' );
Same here. It's very likely that the test script is, 20% of the time, running either so fast or so slow that it's updating files "within the same second" sometimes and not other times and Slay::Maker is thereby sometimes updating a file and sometimes not. I can't recall which assumption Slay::Maker makes if a master file A0 and a dependent file A1 (where A1 is built from A0) have identical filesystem dates. One could assume that A1 is up to date and need not be built, or one could assume (conservatively) that it it not up to date and rebuild it just to be sure. While the latter is rare, it comes in to play when you can run multiple make commands within the same second and updating A0 in between. And to think that some older filesystems have a *2* second resolution on their mod_time! A well-placed sleep in make.t could make this problem become stable (by preventing it or by making it always occur). - Barrie
CC: ANDK [...] cpan.org
Subject: Re: [rt.cpan.org #28627] Random test results
Date: Wed, 12 Sep 2007 05:57:06 +0200
To: bug-Slay-Maker [...] rt.cpan.org
From: andreas.koenig.7os6VVqR [...] franz.ak.mind.de (Andreas J. Koenig)
Show quoted text
>>>>> On Mon, 06 Aug 2007 11:41:07 -0400, "Mark Nodine via RT" <bug-Slay-Maker@rt.cpan.org> said:
Show quoted text
Show quoted text
> I sent an email to the original developer of Slay::Maker (I only updated > it to get rid of pseudohashes, which are no longer supported in perl > 5.9.5 and to make a few minor enhancements). Here is his response:
Show quoted text
> Hmm, comments inline below, in case they help.
>> >> t/make....# Test 45 got: "1" (t/make.t at line 372) >> # Expected: "" >> # t/make.t line 372 is: ok( join(',',@new_stats[8,9]) eq >> join(',',@file_0_stats[8,9]), '' ) ;
Show quoted text
> This is testing to see if file 0 has been re-made; it should not have > been, but has been.
This statement seems to contradict the fact that the test immediately before this test has a C<< force=>1 >>. Show quoted text
> If you can reproduce this, try removing the "eq" > and replacing it with a "," in those two tests so it'll dump out the > numbers on a good test and a bad test, that way we can be sure it's the > mod_time and not the size that is changing.
This I did and this is the result: % make test [CPANSHELL] make[1]: Entering directory `/home/k/.cpan/build/Slay-Maker-0.05-BZgZMp' PERL_DL_NONLAZY=1 /home/src/perl/repoperls/installed-perls/perl/pSYX0BQ/perl-5.8.0@31843/bin/perl "-MExtUtils::Command::MM" "-e" "test_harness(0, 'blib/lib', 'blib/arch')" t/*.t t/make....NOK 45/60# Test 45 got: "1189568219,1189568220" (t/make.t at line 372) # Expected: "1189568219,1189568219" # t/make.t line 372 is: ok( join(',',@new_stats[8,9]), join(',',@file_0_stats[8,9]) ) ; t/make....NOK 48/60# Test 48 got: "16;1189568219;1189568220" (t/make.t at line 388) # Expected: "16;1189568219;1189568219" # t/make.t line 388 is: ok( join(';',@new_stats[7..9]), join(';',@file_0_stats[7..9]) ); t/make....FAILED tests 45, 48 Failed 2/60 tests, 96.67% okay Failed Test Stat Wstat Total Fail List of Failed ------------------------------------------------------------------------------- t/make.t 60 2 45 48 Failed 1/1 test scripts. 2/60 subtests failed. Files=1, Tests=60, 2 wallclock secs ( 0.58 cusr + 0.18 csys = 0.76 CPU) Failed 1/1 test programs. 2/60 subtests failed. make[1]: *** [test_dynamic] Fehler 255 make[1]: Leaving directory `/home/k/.cpan/build/Slay-Maker-0.05-BZgZMp' So it is not the size but the mtime. Show quoted text
>> # Test 48 got: "1" (t/make.t at line 388) >> # Expected: "" >> # t/make.t line 388 is: ok( join(';',@new_stats[7..9]) eq >> join(';',@file_0_stats[7..9]), '' );
> Same here.
Show quoted text
> It's very likely that the test script is, 20% of the time, running > either so fast or so slow that it's updating files "within the same > second" sometimes and not other times and Slay::Maker is thereby > sometimes updating a file and sometimes not. I can't recall which > assumption Slay::Maker makes if a master file A0 and a dependent file A1 > (where A1 is built from A0) have identical filesystem dates. One could > assume that A1 is up to date and need not be built, or one could assume > (conservatively) that it it not up to date and rebuild it just to be > sure. While the latter is rare, it comes in to play when you can run > multiple make commands within the same second and updating A0 in > between. And to think that some older filesystems have a *2* second > resolution on their mod_time!
Show quoted text
> A well-placed sleep in make.t could make this problem become stable (by > preventing it or by making it always occur).
That would be after line 365. I added the sleep 1 there: 362 ## See if utime and atime are not restored when the size changes. 363 sub { 364 tweak_file_0() ; 365 age_file_0() ; 366 sleep 1; 367 $m->make( $file_0_name, {force=>1, detect_no_size_change=>1} ) ; 368 ok( $m->output, "created $file_0_name" ) ; 369 }, With this change the test always fails. I suggest removing the two tests, they seem plain wrong. -- andreas