Re: change in handling missing data.

[Daniel J S. <dan...@ie...>]

Ethan A Merritt wrote:

> plot "t.dat" using 1:2
> ======================
> Each sample counts as 0.01 seconds.
>   %   cumulative   self              self     total
>  time   seconds   seconds    calls   s/call   s/call  name
>  27.98      2.37     2.37  1000000     0.00     0.00  store2d_point
>  20.19      4.08     1.71  1000000     0.00     0.00  df_tokenise
>  15.23      5.37     1.29  1000041     0.00     0.00  PS_vector
>  13.70      6.53     1.16  1000001     0.00     0.00  df_readascii
>  10.15      7.39     0.86  1000001     0.00     0.00  df_gets
>   7.79      8.05     0.66        1     0.66     1.99  plot_lines
>   2.01      8.22     0.17        1     0.17     6.44  get_data
>   0.83      8.29     0.07  2000000     0.00     0.00  gp_strtod
>   0.59      8.34     0.05  2000000     0.00     0.00  check_missing
>   0.59      8.39     0.05  1000001     0.00     0.00  df_readline
>  
> plot "t.dat" using $1:$2
> ========================
> Each sample counts as 0.01 seconds.
>   %   cumulative   self              self     total
>  time   seconds   seconds    calls   s/call   s/call  name
>  20.97      2.65     2.65  1000000     0.00     0.00  df_tokenise
>  19.46      5.11     2.46  1000000     0.00     0.00  store2d_point
>  15.51      7.07     1.96  1000001     0.00     0.00  df_readascii
>   9.18      8.23     1.16  1000041     0.00     0.00  PS_vector
>   8.23      9.27     1.04  1000001     0.00     0.00  df_gets
>   5.66      9.99     0.72  2000002     0.00     0.00  evaluate_at
>   4.67     10.58     0.59        1     0.59     1.78  plot_lines
>   2.85     10.94     0.36        1     0.36    10.70  get_data
>   1.78     11.16     0.23  2000000     0.00     0.00  f_dollars
>   1.62     11.37     0.21  2000002     0.00     0.00  execute_at
>   1.50     11.56     0.19  2000002     0.00     0.00  push
>   1.27     11.72     0.16  2000002     0.00     0.00  pop
>   1.27     11.88     0.16  2000000     0.00     0.00  check_missing
>   1.11     12.02     0.14  4000000     0.00     0.00  real
>   1.03     12.15     0.13  1000001     0.00     0.00  df_readline
>   0.87     12.26     0.11  2000057     0.00     0.00  Gcomplex
>   0.71     12.35     0.09  2000000     0.00     0.00  gp_strtod
>   0.55     12.42     0.07  2000002     0.00     0.00  check_stack
>   0.36     12.46     0.05                             df_determine_matrix_info
>   0.32     12.50     0.04                             more_on_stack
>   0.24     12.53     0.03  2000002     0.00     0.00  reset_stack
> 
> As Daniel said, the extra time is due to the overhead of
> evaluating each coordinate as an expression rather than as a constant.
> ( evaluate_at f_dollars push pop check_stack reset_stack )

I would have thought that evaluate_at or execute_at would have been where the increase is,  but that doesn't appear to be much in either case.  I would say PS_vector would be the same amount of CPU in both cases.  In the first case it is 15% in the second 9%.  That would mean 0.15 Total_1 = 0.9 Total_2, or Total_2 = 1.67 Total_1.  Is my thinking correct on that?  So a 67% increase in CPU consumption?

> I don't see any horrible time-wasters in the profile, even when I break
> it down to individual lines of code.  However, I still don't know which
> bit, exactly, is being accounted for as "system time". Perhaps there
> is some system call we can manage to do with out, but at present I
> can't think what it would be.

Good question.  evaluate_at, execute_at, push, pop, real, Gcomplex, check_stack, more_on_stack, and reset_stack don't appear to have an system calls.  df_determine_matrix_info has an "fseek" which is something that could be a potential time waster, however gprof doesn't indicate that being called 1 million times.

I'm not sure why df_determine_matrix_info is called in one case over the other, but what is peculiar is that gprof doesn't have anythingthing listed under the number of calls for df_determine_matrix_info or more_on_stack.

Dan