Discussion related to cado-nfs

[Emmanuel Thomé <Emmanuel.Thome@inria.fr>]

Hi,

Thanks for your report !

Our fault, for sure. Information is not very usable, here.

We report timings in two ways.

Timings that are printed as "Total cpu/real time for XXX" are counted by
cado-nfs.py itself, based on the cpu time of its child processes, and on
the clock difference.

In other cases (when we read "Aggregated timings for YYY"), we report what 
the individual cado-nfs programs currently
report, based on regexps that we use to extract the timing info from the
data files (these regexps are in ./scripts/cadofactor/cadotask.py). This
may (as in the lattice sieving case) contain data that can be directly
interpreted towards a global cpu time count. In other cases (as in the
case of linear algebra), it's a bit quirky. But anyway for linear algebra
we do have the "cpu/real" time line anyway, so extra stats should only be
understood as "bonus".


There are several potential pitfalls:

 - some programs report timing info differently from others.

 - our regexps sometime fail because they don't follow the volution of
   the program printout. I've just added a flag so that we can track such
   divergence cases.

When you get messages such as:

> Warning:XXXXXXXXXXXX: some stats could not be displayed for YYYYYYYYYYY 
> (see log file for debug info)

it means that the latter condition happened. Except that in your case,
there is no polynomial selection to work with, so it's pretty normal that
cado-nfs couldn't find any timing to report for polynomial selection.
I've fixed that as well.

You're also seeing an inconsistency in that the timing report for the
linear algebra stage is only giving you the WCT (wall-clock time) of the
krylov and mksol steps, not the aggregated CPU time. This was an
oversight, which I'm also fixing.  However, this does count to the total
that the program prints, so it can't be the explanation of your problem.
And by the way, you've correctly omitted these counts from your sum.


> But the addition of intermediate results doesn't give the total.
> 4.72+102.51+785028+57.22+472.92+388.88+328.58+89.74+100411+82.81+680.74
> gives 887647.12, not the 1551370 see as a total.
> 
> The total seems ok. So I may miss some intermediate results or I may
> misinterpret some data.


1551370 is ok ? Then yes, that's rather weird. How many threads did you
have per las program ? Would it be possible to share the log file so that
I can have a look ?

Best,

E.


On Sat, Sep 05, 2020 at 01:56:25PM +0200, eric.jeancolas@free.fr wrote:
> Hello
> 
> For one number, a c160 with SNFS, I got the following end of sysout log.
> 
> Info:Square Root: Factors: 
> 626816785777451600758981838272270646850682251997773636331126303903 
> 6472832583977168929436763320576275854833857768912955644720878207260226100095188285172984249397
> Warning:Polynomial Selection (size optimized): some stats could not be 
> displayed for polyselect1 (see log file for debug info)
> Warning:Polynomial Selection (root optimized): some stats could not be 
> displayed for polyselect2 (see log file for debug info)
> Info:Generate Factor Base: Total cpu/real time for makefb: 4.72/2.01359
> Info:Generate Free Relations: Total cpu/real time for freerel: 102.51/26.282
> Info:Lattice Sieving: Aggregate statistics:
> Info:Lattice Sieving: Total number of relations: 28042254
> Info:Lattice Sieving: Average J: 1894.87 for 3517286 special-q, max bucket 
> fill -bkmult 1.0,1s:1.081640
> Info:Lattice Sieving: Total time: 785028s
> Info:Filtering - Duplicate Removal, splitting pass: Total cpu/real time for 
> dup1: 57.22/119.639
> Info:Filtering - Duplicate Removal, splitting pass: Aggregate statistics:
> Info:Filtering - Duplicate Removal, splitting pass: CPU time for dup1: 
> 118.9s
> Info:Filtering - Duplicate Removal, removal pass: Total cpu/real time for 
> dup2: 472.92/438.735
> Info:Filtering - Duplicate Removal, removal pass: Aggregate statistics:
> Info:Filtering - Duplicate Removal, removal pass: CPU time for dup2: 
> 378.59999999999997s
> Info:Filtering - Singleton removal: Total cpu/real time for purge: 
> 388.88/400.862
> Info:Filtering - Merging: Merged matrix has 2351820 rows and total weight 
> 404898763 (172.2 entries per row on average)
> Info:Filtering - Merging: Total cpu/real time for merge: 328.58/94.9078
> Info:Filtering - Merging: Total cpu/real time for replay: 89.74/77.1238
> Info:Linear Algebra: Total cpu/real time for bwc: 100411/25707.4
> Info:Linear Algebra: Aggregate statistics:
> Info:Linear Algebra: Krylov: WCT time 16545.96, iteration CPU time 0.21, 
> COMM 0.01, cpu-wait 0.0, comm-wait 0.0 (73728 iterations)
> Info:Linear Algebra: Lingen CPU time 469.42, WCT time 136.78
> Info:Linear Algebra: Mksol: WCT time 8786.49, iteration CPU time 0.23, COMM 
> 0.01, cpu-wait 0.0, comm-wait 0.0 (36864 iterations)
> Info:Quadratic Characters: Total cpu/real time for characters: 82.81/34.1738
> Info:Square Root: Total cpu/real time for sqrt: 680.74/214.047
> Info:HTTP server: Shutting down HTTP server
> Info:Complete Factorization / Discrete logarithm: Total cpu/elapsed time 
> for entire factorization: 1.55137e+06/419762
> Info:root: Cleaning up computation data in /tmp/cado.ej7v99s4
> 
> I use a 4-core CPU, so the ratio at the end Total cpu/elapsed time = 
> 1.55137e+06/419762 = 3.7 is consistent.
> But the addition of intermediate results doesn't give the total.
> 4.72+102.51+785028+57.22+472.92+388.88+328.58+89.74+100411+82.81+680.74 
> gives 887647.12, not the 1551370 see as a total.
> 
> The total seems ok. So I may miss some intermediate results or I may 
> misinterpret some data.
> 
> Could you please help me understand these data?
> 
> Best regards.
> _______________________________________________
> Cado-nfs-discuss mailing list
> Cado-nfs-discuss@lists.gforge.inria.fr
> https://lists.gforge.inria.fr/mailman/listinfo/cado-nfs-discuss