On Wed, Feb 24, 2010 at 03:46:08PM +0000, Tim Bunce wrote: > On Wed, Feb 24, 2010 at 02:43:44PM +0000, Nicholas Clark wrote: > > On Wed, Feb 24, 2010 at 10:42:03AM +0000, [email protected] wrote: > > > Revision: 1081 > > > Author: tim.bunce > > > Date: Wed Feb 24 02:40:49 2010 > > > Log: More refinements to shed light on freebsd test failures like > > > http://www.cpantesters.org/cpan/report/6859183 > > > > I can replicate this: > > > > t/61-cputime.t ......... 1/15 profile_this() using > > /home/nick/Sandpit/snap5.9.x-v5.11.5-25-g1369b85/bin/perl5.11.5 -d:NYTProf > > with > > NYTPROF=compress=1:file=nytprof_61-cputime.out:leave=0:savesrc=0:slowops=0:start=init:stmts=0:use_db_sub=0:usecputime=1 > > step 0.007812 1267019778.081813 > > tick 0.0156 1267019779.089130 > > tick 0.0234 1267019779.096045 > > tick 0.0312 1267019779.126041 > > [...] > > tick 0.3984 1267019780.317689 > > tick 0.4062 1267019780.336896 > > cputime loop count 156536 > > t/61-cputime.t ......... 2/15 > > # Failed test 'cputime of foo() should be not much more than 0.4' > > # at t/61-cputime.t line 38. > > # '1.25' > > # < > > # '1' > > > I have no idea what to do next. > > Me neither. The 1.25 doesn't make much sense. > > What does the latest version of that test report?
t/61-cputime.t ......... 1/15 profile_this() using /home/nick/Sandpit/snap5.9.x-v5.11.5-25-g1369b85/bin/perl5.11.5 -d:NYTProf with NYTPROF=compress=1:file=nytprof_61-cputime.out:leave=0:savesrc=0:slowops=0:start=init:stmts=0:use_db_sub=0:usecputime=1 step 0.007812 1267026886.624712 tick 0.0156 1267026887.641010 tick 0.0234 1267026887.693983 tick 0.0312 1267026887.746461 tick 0.0391 1267026887.791448 tick 0.0469 1267026887.798949 tick 0.0547 1267026887.833041 tick 0.0625 1267026887.840538 tick 0.0703 1267026887.871023 tick 0.0781 1267026887.878521 tick 0.0859 1267026887.886018 tick 0.0938 1267026887.893516 tick 0.1016 1267026888.009382 tick 0.1094 1267026888.021084 tick 0.1172 1267026888.058084 tick 0.1250 1267026888.081656 tick 0.1328 1267026888.090120 tick 0.1406 1267026888.098573 tick 0.1484 1267026888.106995 tick 0.1562 1267026888.122989 tick 0.1641 1267026888.207050 tick 0.1719 1267026888.253355 tick 0.1797 1267026888.261426 tick 0.1875 1267026888.283916 tick 0.1953 1267026888.298914 tick 0.2031 1267026888.306540 tick 0.2109 1267026888.325285 tick 0.2188 1267026888.332778 tick 0.2266 1267026888.340276 tick 0.2344 1267026888.392758 tick 0.2422 1267026888.422749 tick 0.2500 1267026888.437741 tick 0.2578 1267026888.486858 tick 0.2656 1267026888.501852 tick 0.2734 1267026888.558201 tick 0.2812 1267026888.603184 tick 0.2891 1267026888.622276 tick 0.2969 1267026888.659770 tick 0.3047 1267026888.723650 tick 0.3125 1267026888.738647 tick 0.3203 1267026888.761134 tick 0.3281 1267026888.768635 tick 0.3359 1267026888.783631 tick 0.3438 1267026888.828755 tick 0.3516 1267026888.890061 tick 0.3594 1267026888.936305 tick 0.3672 1267026888.944779 tick 0.3750 1267026888.983177 tick 0.3828 1267026889.020666 tick 0.3906 1267026889.035660 tick 0.3984 1267026889.043159 tick 0.4062 1267026889.058154 cputime loop count 180767 t/61-cputime.t ......... 2/15 ticks_per_sec 128 # Failed test 'cputime of foo() should be not much more than 0.4' # at t/61-cputime.t line 41. # '1.4375' # < # '1' profile_this() using /home/nick/Sandpit/snap5.9.x-v5.11.5-25-g1369b85/bin/perl5.11.5 -d:NYTProf with NYTPROF=compress=1:file=nytprof_61-cputime.out:leave=0:savesrc=0:slowops=0:start=init:stmts=0:use_db_sub=1:usecputime=1 step 0.007812 1267026890.302205 tick 0.0156 1267026891.309446 tick 0.0234 1267026891.316942 tick 0.0312 1267026891.324431 tick 0.0391 1267026891.339427 tick 0.0469 1267026891.346929 tick 0.0547 1267026891.354422 tick 0.0625 1267026891.365560 tick 0.0703 1267026891.373046 tick 0.0781 1267026891.410695 tick 0.0859 1267026891.418514 tick 0.0938 1267026891.449015 tick 0.1016 1267026891.464962 tick 0.1094 1267026891.473359 tick 0.1172 1267026891.519432 tick 0.1250 1267026891.553969 tick 0.1328 1267026891.561465 tick 0.1406 1267026891.568964 tick 0.1484 1267026891.576461 tick 0.1562 1267026891.583958 tick 0.1641 1267026891.606457 tick 0.1719 1267026891.613950 tick 0.1797 1267026891.628950 tick 0.1875 1267026891.636442 tick 0.1953 1267026891.643946 tick 0.2031 1267026891.674435 tick 0.2109 1267026891.711921 tick 0.2188 1267026891.727020 tick 0.2266 1267026891.742513 tick 0.2344 1267026891.773409 tick 0.2422 1267026891.789330 tick 0.2500 1267026891.820374 tick 0.2578 1267026891.836355 tick 0.2656 1267026891.934819 tick 0.2734 1267026891.965969 tick 0.2812 1267026891.974182 tick 0.2891 1267026892.049932 tick 0.2969 1267026892.057419 tick 0.3047 1267026892.102907 tick 0.3125 1267026892.110414 tick 0.3203 1267026892.140317 tick 0.3281 1267026892.192791 tick 0.3359 1267026892.214810 tick 0.3438 1267026892.233679 tick 0.3516 1267026892.256669 tick 0.3594 1267026892.264165 tick 0.3672 1267026892.279164 tick 0.3750 1267026892.395831 tick 0.3828 1267026892.418228 tick 0.3906 1267026892.471203 tick 0.3984 1267026892.478698 tick 0.4062 1267026892.501193 cputime loop count 141164 t/61-cputime.t ......... 9/15 ticks_per_sec 128 # Failed test 'cputime of foo() should be not much more than 0.4' # at t/61-cputime.t line 41. # '1.1953125' # < # '1' # Looks like you failed 2 tests of 15. t/61-cputime.t ......... Dubious, test returned 2 (wstat 512, 0x200) > And what does this say (after make install): > > NYTPROF=stmts=0:trace=4:start=init:slowops=0 perl -d:NYTProf -x > t/61-cputime.t 2>&1 | grep main::foo 1 -> sub main::foo from main::RUNTIME @1:47 (d1, oh 0.000000t, sub 0.587561s) #20718 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.587561s) #20719 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.587618s) #20720 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.587646s) #20721 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.587701s) #20722 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.587728s) #20723 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.587759s) #20724 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.587789s) #20725 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.587818s) #20726 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.587891s) #20727 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.587948s) #20728 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.587980s) #20729 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588008s) #20730 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588038s) #20731 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588115s) #20732 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588158s) #20733 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588257s) #20734 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588356s) #20735 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588408s) #20736 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588467s) #20737 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588501s) #20738 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588579s) #20739 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588616s) #20740 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588655s) #20741 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588694s) #20742 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588728s) #20743 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588762s) #20744 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.588988s) #20745 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589016s) #20746 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589071s) #20747 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589117s) #20748 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589158s) #20749 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589196s) #20750 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589252s) #20751 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589292s) #20752 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589349s) #20753 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589396s) #20754 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589444s) #20755 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589479s) #20756 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589534s) #20757 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589585s) #20758 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589630s) #20759 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589665s) #20760 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589707s) #20761 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589743s) #20762 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589770s) #20763 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589799s) #20764 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589853s) #20765 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589914s) #20766 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589954s) #20767 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.589980s) #20768 2 >> entersub at 1:23 from main::foo (inherited) (seix 276->472, ac0) 2 ->xsub Time::HiRes::time from main::foo @1:23 (d1, oh 0.000000t, sub 0.590006s) #20769 1 <- main::foo 2.529912s excl = 2.532387s incl - 0.002475s (0.590036-0.587561), oh 0.000000-0.000000=0.000000t, d1 @1:47 #20718 0x826a114 Sub main::foo fid 1 lines 11..30 Time::HiRes::time called by main::foo at 1:23: count 51 (i0.002475s e0.002475s, d0 ri0.000000s) main::foo called by main::RUNTIME at 1:47: count 1 (i2.532387s e2.529912s, d0 ri0.000000s) > Tim [who should be packing...]. A conference? Nicholas Clark -- You've received this message because you are subscribed to the Devel::NYTProf Development User group. Group hosted at: http://groups.google.com/group/develnytprof-dev Project hosted at: http://perl-devel-nytprof.googlecode.com CPAN distribution: http://search.cpan.org/dist/Devel-NYTProf To post, email: [email protected] To unsubscribe, email: [email protected]
