Re: change in handling missing data.

[Ethan A M. <merritt@u.washington.edu>]

On Sunday 06 August 2006 10:07 pm, Dmitri A. Sergatskov wrote:
> For the benchamrk I made 2 column data file
> x = (-10,10), y = sin(x)
> with 1e6 (one million) rows.
> 
> plot "t.dat" using 1:2
> 
> [dima@das200 tmp]$ time gnuplot < cmd
> 
> real    0m3.831s
> user    0m3.528s
> sys     0m0.176s
> 
> plot "t.dat" using ($1):($2)
> 
> [dima@das200 tmp]$ time gnuplot < cmd
> 
> real    0m11.086s
> user    0m5.828s
> sys     0m4.600s

OK, I can confirm that to some extent.
Benchmarked on a hyperthreaded P4 at 2.6GHz
(I used  set term post; set output '/dev/null')

For  plot "t.dat" using 1:2
2.665u 0.094s 0:02.75 100.0%    0+0k 0+0io 0pf+0w

For plot "t.dat" using ($1):($2) 
4.456u 2.342s 0:06.79 100.0%    0+0k 0+0io 0pf+0w

> I did multiple passes, so I am pretty sure the data file is in disk cache. 
> All this is on FedoraCore 5/ Pentiun4 2.6GHz / 2GB of RAM

So it runs faster on my machine, but yes it spends more time on the second test.
Here are the gprof outputs:

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 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.

-- 
Ethan A Merritt
Biomolecular Structure Center
University of Washington, Seattle 98195-7742