[Bug fortran/38199] New: missed optimization, regression: I/O performance

[Bug fortran/38199] New: missed optimization, regression: I/O performance

[manfred99 at gmx dot ch]

With

!234567
      character buffer*10000000
      integer i,j

      DO j=1,20
        write(buffer,'(i2)') j
        write(*,*) buffer(1:2)
        read(buffer,*) i
        write(*,*) i
      ENDDO
      end

I get the following timings:
ifort11 (64bit):               0.306s
ifort9 (32bit):                0.562s
g77 (32bit):                   2.786s
gfortran4.3 (64bit):           3.906s
gfortran4.4 (20081120, 64bit): 4.832s


Even worse:
!234567
      character buffer*100000
      integer i,j

      DO j=1,9999
        write(buffer,'(i4)') j
        write(*,*) buffer(1:4)
        read(buffer,*) i
        write(*,*) i
      ENDDO
      end

ifort11 (64bit):                0.458s
g77 (32bit):                   13.283s
gfortran4.3 (64bit):           19.362s
gfortran4.4 (20081120, 64bit): 23.917s


This is a very realistic real-world scenario when reading
in a flat-file of unknown width (<100000 assumed), and
then processing the received string buffer, i.e. doing
    100 read(10,'(a)',END=999) buffer
        ---> 
        read(buffer,*,END=101,ERR=101) array
    101 do something when unexpected content
        GOTO 100
    999 end


-- 
           Summary: missed optimization, regression: I/O performance
           Product: gcc
           Version: 4.4.0
            Status: UNCONFIRMED
          Severity: normal
          Priority: P3
         Component: fortran
        AssignedTo: unassigned at gcc dot gnu dot org
        ReportedBy: manfred99 at gmx dot ch


http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

[Bug fortran/38199] missed optimization, regression: I/O performance

[jb at gcc dot gnu dot org]

------- Comment #1 from jb at gcc dot gnu dot org  2008-11-20 14:04 -------
I'm looking at I/O performance as part of PR 25561 (see also PR 37754, perhaps
this is a dup?), but my changes are invasive enough that they are 4.5 material.
Thanks for the report.


-- 

jb at gcc dot gnu dot org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |jb at gcc dot gnu dot org
             Status|UNCONFIRMED                 |NEW
     Ever Confirmed|0                           |1
   Last reconfirmed|0000-00-00 00:00:00         |2008-11-20 14:04:55
               date|                            |


http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

[Bug fortran/38199] missed optimization, regression: I/O performance

[manfred99 at gmx dot ch]

------- Comment #2 from manfred99 at gmx dot ch  2008-11-20 14:59 -------
The profiling of the second testcase gives
  %   cumulative   self              self     total
 time   seconds   seconds    calls  Ts/call  Ts/call  name
 44.20      8.34     8.34                             next_char
 24.85     13.03     4.69                             mem_read
 17.04     16.25     3.22                             memcpy
  4.98     17.19     0.94                             eat_spaces
  4.03     17.95     0.76                            
_gfortrani_empty_internal_buffer
  2.44     18.41     0.46                             nml_query
  2.09     18.80     0.40                             strncasecmp_l
  0.21     18.84     0.04                             memset
  0.05     18.85     0.01                             __divti3
  0.05     18.86     0.01                             _gfortrani_write_block
  0.05     18.87     0.01                             next_char
  0.00     18.87     0.00        1     0.00     0.00  MAIN__


It seems gfortran reads character by character and does not take
any opportunities to shortcut the read process.

For this case, one could imagine that the read routine would scan for the
last non-blank character and would stop reading at this position.

Perhaps ifort is doing exactly this.


-- 


http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

[Bug fortran/38199] [4.4 regression] I/O performance

[burnus at gcc dot gnu dot org]

------- Comment #3 from burnus at gcc dot gnu dot org  2008-11-20 15:56 -------
Jerry, regarding the suggestion in comment 2: Do you see that we can do there
some optimization, esp. when reading a number or with "*" a string (for '(a)'
one presumably cannot do any optimization and has to read past all blanks).  


-- 

burnus at gcc dot gnu dot org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |jvdelisle at gcc dot gnu dot
                   |                            |org
           Keywords|                            |missed-optimization
           Priority|P3                          |P4
            Summary|missed optimization,        |[4.4 regression] I/O
                   |regression: I/O performance |performance


http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

[Bug fortran/38199] [4.4 regression] I/O performance

[manfred99 at gmx dot ch]

------- Comment #4 from manfred99 at gmx dot ch  2008-11-20 16:09 -------
Consider
!234567
      program internalread3
      implicit none
      character value*100000
      integer i,j

      DO j=1,9999
        write(value,'(i4)') j
        write(*,*) value(1:4)
        read(value(1:LEN_TRIM(value)),*) i
        write(*,*) i
      ENDDO
      end program internalread3

gfortran4.4 (20081120, 64bit): 1.079s

i.e. speedup by factor 23 ...
but there are cases where the user can't solve the issue like this.
And such basic optimizations are more efficiently done
by the compiler.

Besides this: This is an internal read, so the compiler has full
control over the contents of this string variable. It can e.g.
null terminate the string or similar, or it can carry on an index 
of the last character in string (set on assignment), or ... 


-- 


http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

[Bug fortran/38199] [4.4 regression] I/O performance

[jvdelisle at gcc dot gnu dot org]

------- Comment #5 from jvdelisle at gcc dot gnu dot org  2008-11-21 04:14 -------
Regarding comment #2.  This is exactly the area I have been investigating, but
I don't have anything solid yet.


-- 


http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

[Bug fortran/38199] missed optimization: I/O performance

[pault at gcc dot gnu dot org]

------- Comment #6 from pault at gcc dot gnu dot org  2008-11-21 13:54 -------
I do not believe that it is a regression, so I have removed that from the
summary.

The profiling that you have done tells a story - I think that it is fairly
clear where the problem lies; not in making a spurious copy as I first thought
but rather in looking for an end of record, or some such foolishness.

I had a brief look in the library to try to understand why so much time is
spent in next_char, mem_read and memcpy and cannot immediately see what is
happening.  Jerry knows the terrain better than me.

Cheers

Paul


-- 

pault at gcc dot gnu dot org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
            Summary|[4.4 regression] I/O        |missed optimization: I/O
                   |performance                 |performance


http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

[Bug fortran/38199] missed optimization: I/O performance

[jvdelisle at gcc dot gnu dot org]

------- Comment #7 from jvdelisle at gcc dot gnu dot org  2008-11-22 05:34 -------
I think this is then a dup of 37754.  Janne is working some ideas and these are
similar to my thoughts.  This fix here is in a high bug domain so we think we
should hold for 4.5, get it resolved and tested, then possibly backport to 4.4

Marking as duplicate.

*** This bug has been marked as a duplicate of 37754 ***


-- 

jvdelisle at gcc dot gnu dot org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|                            |DUPLICATE


http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

[Bug fortran/38199] missed optimization: I/O performance

[jvdelisle at gcc dot gnu dot org]

------- Comment #8 from jvdelisle at gcc dot gnu dot org  2010-02-13 06:39 -------
I am reopening this bug.  I stumbled upon it searching testcases from Manfred, 
Running the test case here with 4.5 has not substantially improved.  Time to
put on my thinking cap.


-- 

jvdelisle at gcc dot gnu dot org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |REOPENED
         Resolution|DUPLICATE                   |


http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

[Bug fortran/38199] missed optimization: I/O performance

[jvdelisle at gcc dot gnu dot org]

------- Comment #9 from jvdelisle at gcc dot gnu dot org  2010-02-13 06:40 -------
Assigning to myself.


-- 

jvdelisle at gcc dot gnu dot org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
         AssignedTo|unassigned at gcc dot gnu   |jvdelisle at gcc dot gnu dot
                   |dot org                     |org
             Status|REOPENED                    |ASSIGNED
   Last reconfirmed|2008-11-20 14:04:55         |2010-02-13 06:40:14
               date|                            |


http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

[Bug fortran/38199] missed optimization: I/O performance

[jvdelisle at gcc dot gnu dot org]

------- Comment #10 from jvdelisle at gcc dot gnu dot org  2010-02-21 15:59 -------
An update.  I have a patch developing.  Conceptually, it requires handling of
separators in list_read.c to be moved to the beginning of each invocation of
list_formatted_read_scalar.  This avoids trying to eat_spaces or separators
after a value is read.  This change is actually the right thing to do since it
takes code scattered in several places and consolidates it to one place.

The result is execution time on the original testcase is reduced to less then
.2 seconds. I don't expect significant performance gains in general, though the
code should be more maintainable

The patch is a bit intrusive, especially in namelist areas, so may be best for
4.6 at this stage. (assuming I get it to work completely at all :) )


-- 


http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

[Bug fortran/38199] missed optimization: I/O performance

[steven at gcc dot gnu.org]

http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

Steven Bosscher <steven at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |steven at gcc dot gnu.org

--- Comment #14 from Steven Bosscher <steven at gcc dot gnu.org> 2012-03-11 22:41:25 UTC ---
Jerry, are you still working on this?

[Bug fortran/38199] missed optimization: I/O performance

[jb at gcc dot gnu.org]

http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

--- Comment #13 from Janne Blomqvist <jb at gcc dot gnu.org> 2011-05-10 09:41:08 UTC ---
Here's something for formatted writes; consider the write-many.f (from some
other PR, I'm too lazy to check which now)

program main
  open(10,status='SCRATCH')
  a = 0.3858204
  do i=1,1000000
     a = a + 0.4761748164
     write(10, '(G12.5)'),a
  end do
end program main

Profiling this with 'perf' shows the top offenders as

# Overhead         Command                                                     
Shared Object  Symbol
# ........  .............. 
.................................................................  ......
#
    21.56%      write-many  /lib/libc-2.11.1.so                                
               [.] __mpn_divrem
    14.72%      write-many  /lib/libc-2.11.1.so                                
               [.] ___printf_fp
    13.42%      write-many  /lib/libc-2.11.1.so                                
               [.] hack_digit.15661
     7.75%      write-many  /lib/libc-2.11.1.so                                
               [.] __GI_vfprintf
     3.81%      write-many 
/home/janne/src/gfortran/trunk/install/lib64/libgfortran.so.3.0.0  [.]
output_float.isra.7.constprop.16
     2.81%      write-many 
/home/janne/src/gfortran/trunk/install/lib64/libgfortran.so.3.0.0  [.]
write_float
     2.38%      write-many  /lib/libc-2.11.1.so                                
               [.] _IO_default_xsputn_internal
     2.10%      write-many 
/home/janne/src/gfortran/trunk/install/lib64/libgfortran.so.3.0.0  [.]
data_transfer_init
     1.96%      write-many 
/home/janne/src/gfortran/trunk/install/lib64/libgfortran.so.3.0.0  [.]
formatted_transfer
     1.37%      write-many 
/home/janne/src/gfortran/trunk/install/lib64/libgfortran.so.3.0.0  [.]
next_format0


That is, most of the time seems to be spent somewhere related to the libc
formatting (as we're using snprintf to convert the real numbers to ascii).
Next, consider

#include <stdio.h>
#include <stdlib.h>

int main(int argc, char *argv[])
{
        int ndigits = atoi(argv[1]);
        printf("Doing test with %d digits\n", ndigits);
        size_t bufsz = ndigits + 9;
        char *buf = malloc(bufsz);
        for (int i = 0; i < 10000000; i++)
                snprintf(buf, bufsz, "%#-.*e", ndigits, 1./3);
        printf("%s\n", buf);
        return 0;
}

$ time ./snprintfbench 0
Doing test with 0 digits
3.e-01

real    0m2.608s
user    0m2.610s
sys     0m0.000s

$ time ./snprintfbench 20
Doing test with 20 digits
3.33333333333333314830e-01

real    0m4.746s
user    0m4.740s
sys     0m0.010s

$ time ./snprintfbench 40
Doing test with 40 digits
3.3333333333333331482961625624739099293947e-01

real    0m6.362s
user    0m6.360s
sys     0m0.000s

$ time ./snprintfbench 60
Doing test with 60 digits
3.333333333333333148296162562473909929394721984863281250000000e-01

real    0m8.155s
user    0m8.160s
sys     0m0.000s

That is, while there is a constant cost for snprintf(), each additional digit
increases the time approximately linearly. 

Now, in io/write_float.def we always convert with a constant 41 digits (when
REAL(16) is available). Instead, we could first figure out how many digits we
need, and only then call snprintf(), generating only as many digits as needed.
Or as many as requested + 1, if the user has chosen a non-default rounding
mode, that is we need an extra digit in order to do the rounding in that case.

[Bug fortran/38199] missed optimization: I/O performance

[jvdelisle at gcc dot gnu.org]

http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

--- Comment #12 from Jerry DeLisle <jvdelisle at gcc dot gnu.org> 2010-10-23 13:03:08 UTC ---
I got sidetracked by other more serious bugs. I am not even sure I have the
draft patch any more, but I will look for it. Not too sure about 4.6

[Bug fortran/38199] missed optimization: I/O performance

[tkoenig at gcc dot gnu.org]

http://gcc.gnu.org/bugzilla/show_bug.cgi?id=38199

--- Comment #11 from Thomas Koenig <tkoenig at gcc dot gnu.org> 2010-10-23 10:02:46 UTC ---
Hi Jerry,

> An update.  I have a patch developing. 

> The patch is a bit intrusive, especially in namelist areas, so may be best for
> 4.6 at this stage. (assuming I get it to work completely at all :) )

Still in time for 4.6? :-)