bugGNU Octave - Bugs: bug #40304, Excessive I/O in load function...

 
 

bug #40304: Excessive I/O in load function with g++/libstdc++ 4.4

Submitter:  None
Submitted:  Fri 18 Oct 2013 03:58:03 PM UTC
   
 
Category:  Octave Function Severity:  2 - Minor
Priority:  5 - Normal Item Group:  Performance
Status:  Wont Fix Assigned to:  None
Originator Name:  Mike Pacey Originator Email:  -email is unavailable-
Open/Closed:  * Closed Release:  * 3.6.4
Operating System:  * GNU/Linux Fixed Release:  None
Planned Release:  None
* Mandatory Fields

Add a New Comment Rich Markup
   

Jump to the original submission

Thu 13 Feb 2014 11:25:10 PM UTC, comment #22: 

Closing this report as "won't fix". I am fairly certain that the performance hit you are seeing is a libstdc++ bug that has been fixed in subsequent versions of gcc.

Mike Miller <mtmiller>
Group Member
Tue 21 Jan 2014 06:08:03 AM UTC, comment #21: 

Ok, I can now reproduce this behavior but I believe the problem is entirely due to a gcc bug or feature that has subsequently been fixed or improved. You said this behavior shows up on Scientific Linux 6.4, which uses gcc 4.4.7. I can get the same behavior to show on my Debian system by compiling with gcc 4.4.7 and running with the 4.4.7 libstdc++ shared library.

With gcc/g++/libstdc++ 4.4.7:


00:51:13.464509 open("Extended_Molecule", O_RDONLY) = 3
00:51:13.464532 fstat(3, {st_mode=S_IFREG|0640, st_size=3041030, ...}) = 0
00:51:13.464563 lseek(3, 0, SEEK_SET)   = 0
00:51:13.464579 read(3, " # name:", 8)  = 8
00:51:13.464597 lseek(3, 512, SEEK_SET) = 512
00:51:13.464612 read(3, "0\t1\n\t34\t", 8) = 8
00:51:13.464628 lseek(3, 1024, SEEK_SET) = 1024
00:51:13.464643 read(3, "6\t0\t0\t1\n", 8) = 8
00:51:13.464659 lseek(3, 2048, SEEK_SET) = 2048
00:51:13.464674 read(3, "\n\t157\t6\t", 8) = 8
00:51:13.464690 lseek(3, 4096, SEEK_SET) = 4096
00:51:13.464705 read(3, "\t0\t0\t1\n\t", 8) = 8
00:51:13.464721 lseek(3, 8192, SEEK_SET) = 8192
00:51:13.464736 read(3, "0\t0\t1\n\t6", 8) = 8
00:51:13.464752 lseek(3, 16384, SEEK_SET) = 16384
00:51:13.464767 read(3, "241\t6\t0\t", 8) = 8
00:51:13.464783 lseek(3, 32768, SEEK_SET) = 32768
00:51:13.464798 read(3, "6\t0\t0\t1\n", 8) = 8
00:51:13.464814 lseek(3, 65536, SEEK_SET) = 65536
00:51:13.464829 read(3, "\t4752\t6\t", 8) = 8
00:51:13.464846 lseek(3, 131072, SEEK_SET) = 131072
00:51:13.464861 read(3, "433\t6\t0\t", 8) = 8
00:51:13.464877 lseek(3, 262144, SEEK_SET) = 262144
00:51:13.464892 read(3, "9\t\t2099\t", 8) = 8
00:51:13.464908 lseek(3, 524288, SEEK_SET) = 524288
00:51:13.464923 read(3, "6823\t\t68", 8) = 8
00:51:13.464939 lseek(3, 1048576, SEEK_SET) = 1048576
00:51:13.464954 read(3, "00000\n\t1", 8) = 8
00:51:13.464970 lseek(3, 2097152, SEEK_SET) = 2097152
00:51:13.464985 read(3, "0000\n\t1\t", 8) = 8
00:51:13.465007 close(3)                = 0
00:51:13.465030 open("Extended_Molecule", O_RDONLY) = 3
00:51:13.465059 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
00:51:13.465081 close(3)                = 0
00:51:13.465103 open("Extended_Molecule", O_RDONLY) = 3
00:51:13.465125 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
00:51:13.465147 lseek(3, 0, SEEK_SET)   = 0
00:51:13.465164 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
00:51:13.465185 lseek(3, 0, SEEK_SET)   = 0
00:51:13.465201 lseek(3, 116, SEEK_SET) = 116
00:51:13.465217 read(3, "# columns: 5\n\t1\t6\t0\t0\t1\n\t2\t6\t0\t0"..., 8191) = 8191
00:51:13.465234 lseek(3, 124, SEEK_SET) = 124
00:51:13.465250 read(3, "s: 5\n\t1\t6\t0\t0\t1\n\t2\t6\t0\t0\t1\n\t3\t6\t"..., 8191) = 8191
00:51:13.465272 lseek(3, 0, SEEK_SET)   = 0
00:51:13.465291 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
00:51:13.465322 close(3)                = 0
00:51:13.465344 open("Extended_Molecule", O_RDONLY) = 3
00:51:13.465368 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
00:51:13.465401 lseek(3, -8160, SEEK_CUR) = 31
00:51:13.465419 read(3, "\t1\n # name: FermiE\n # type: scal"..., 8191) = 8191
00:51:13.465460 lseek(3, -8156, SEEK_CUR) = 66
00:51:13.465476 read(3, "\t0\n # name: iorb\n # type: matrix"..., 8191) = 8191
00:51:13.465520 mmap(NULL, 425984, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9dd3b4a000
00:51:13.465544 lseek(3, -8128, SEEK_CUR) = 129
00:51:13.465560 read(3, "\t1\t6\t0\t0\t1\n\t2\t6\t0\t0\t1\n\t3\t6\t0\t0\t1"..., 8191) = 8191
00:51:13.465581 lseek(3, -8189, SEEK_CUR) = 131
00:51:13.465596 read(3, "\t6\t0\t0\t1\n\t2\t6\t0\t0\t1\n\t3\t6\t0\t0\t1\n\t"..., 8191) = 8191
00:51:13.465616 lseek(3, -8189, SEEK_CUR) = 133
00:51:13.465631 read(3, "\t0\t0\t1\n\t2\t6\t0\t0\t1\n\t3\t6\t0\t0\t1\n\t4\t"..., 8191) = 8191
00:51:13.465653 lseek(3, -8189, SEEK_CUR) = 135
00:51:13.465668 read(3, "\t0\t1\n\t2\t6\t0\t0\t1\n\t3\t6\t0\t0\t1\n\t4\t6\t"..., 8191) = 8191
00:51:13.465688 lseek(3, -8189, SEEK_CUR) = 137


With gcc/g++/libstdc++ 4.8.2:


00:50:52.688530 open("Extended_Molecule", O_RDONLY) = 3
00:50:52.688554 fstat(3, {st_mode=S_IFREG|0640, st_size=3041030, ...}) = 0
00:50:52.688584 lseek(3, 0, SEEK_SET)   = 0
00:50:52.688601 read(3, " # name:", 8)  = 8
00:50:52.688618 lseek(3, 512, SEEK_SET) = 512
00:50:52.688633 read(3, "0\t1\n\t34\t", 8) = 8
00:50:52.688649 lseek(3, 1024, SEEK_SET) = 1024
00:50:52.688664 read(3, "6\t0\t0\t1\n", 8) = 8
00:50:52.688680 lseek(3, 2048, SEEK_SET) = 2048
00:50:52.688695 read(3, "\n\t157\t6\t", 8) = 8
00:50:52.688711 lseek(3, 4096, SEEK_SET) = 4096
00:50:52.688726 read(3, "\t0\t0\t1\n\t", 8) = 8
00:50:52.688741 lseek(3, 8192, SEEK_SET) = 8192
00:50:52.688756 read(3, "0\t0\t1\n\t6", 8) = 8
00:50:52.688772 lseek(3, 16384, SEEK_SET) = 16384
00:50:52.688787 read(3, "241\t6\t0\t", 8) = 8
00:50:52.688803 lseek(3, 32768, SEEK_SET) = 32768
00:50:52.688818 read(3, "6\t0\t0\t1\n", 8) = 8
00:50:52.688833 lseek(3, 65536, SEEK_SET) = 65536
00:50:52.688848 read(3, "\t4752\t6\t", 8) = 8
00:50:52.688864 lseek(3, 131072, SEEK_SET) = 131072
00:50:52.688879 read(3, "433\t6\t0\t", 8) = 8
00:50:52.688895 lseek(3, 262144, SEEK_SET) = 262144
00:50:52.688910 read(3, "9\t\t2099\t", 8) = 8
00:50:52.688926 lseek(3, 524288, SEEK_SET) = 524288
00:50:52.688940 read(3, "6823\t\t68", 8) = 8
00:50:52.688956 lseek(3, 1048576, SEEK_SET) = 1048576
00:50:52.688971 read(3, "00000\n\t1", 8) = 8
00:50:52.688987 lseek(3, 2097152, SEEK_SET) = 2097152
00:50:52.689002 read(3, "0000\n\t1\t", 8) = 8
00:50:52.689023 close(3)                = 0
00:50:52.689046 open("Extended_Molecule", O_RDONLY) = 3
00:50:52.689074 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
00:50:52.689096 close(3)                = 0
00:50:52.689119 open("Extended_Molecule", O_RDONLY) = 3
00:50:52.689140 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
00:50:52.689162 lseek(3, 0, SEEK_SET)   = 0
00:50:52.689182 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
00:50:52.689204 lseek(3, 0, SEEK_SET)   = 0
00:50:52.689221 lseek(3, 116, SEEK_SET) = 116
00:50:52.689236 read(3, "# columns: 5\n\t1\t6\t0\t0\t1\n\t2\t6\t0\t0"..., 8191) = 8191
00:50:52.689254 lseek(3, 124, SEEK_SET) = 124
00:50:52.689269 read(3, "s: 5\n\t1\t6\t0\t0\t1\n\t2\t6\t0\t0\t1\n\t3\t6\t"..., 8191) = 8191
00:50:52.689288 lseek(3, 0, SEEK_SET)   = 0
00:50:52.689305 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
00:50:52.689334 close(3)                = 0
00:50:52.689353 open("Extended_Molecule", O_RDONLY) = 3
00:50:52.689378 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
00:50:52.689410 lseek(3, 0, SEEK_CUR)   = 8191
00:50:52.689452 lseek(3, 0, SEEK_CUR)   = 8191
00:50:52.689491 mmap(NULL, 425984, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f01d9131000
00:50:52.689515 lseek(3, 0, SEEK_CUR)   = 8191
00:50:52.689533 lseek(3, 0, SEEK_CUR)   = 8191
00:50:52.689550 lseek(3, 0, SEEK_CUR)   = 8191
00:50:52.689568 lseek(3, 0, SEEK_CUR)   = 8191
00:50:52.689585 lseek(3, 0, SEEK_CUR)   = 8191


I can't say for certain that Octave is doing nothing wrong, but it seems that whatever was causing the excessive seeks and reads in the 4.4.7 version of gcc has been fixed or mitigated in a newer version of gcc. I'm marking this as "won't fix" but leaving open for now, if you'd like to investigate further or suggest a change that might help the performance with your compiler.

Mike Miller <mtmiller>
Group Member
Mon 20 Jan 2014 03:40:11 PM UTC, comment #20: 

In regards to comment #17, the problem occurs after saving/loading

In regards to comment #18, the problem also occurs in 3.8.0. Partial strace is:

26796 read(0, "load Extended_Molecule\n", 16384) = 23
26796 stat("Extended_Molecule", {st_mode=S_IFREG|0700, st_size=3041030, ...}) = 0
26796 stat("Extended_Molecule", {st_mode=S_IFREG|0700, st_size=3041030, ...}) = 0
26796 open("Extended_Molecule", O_RDONLY) = 3
26796 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
26796 close(3)                          = 0
26796 open("Extended_Molecule", O_RDONLY) = 3
26796 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
26796 lseek(3, 0, SEEK_SET)             = 0
26796 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
26796 lseek(3, 0, SEEK_SET)             = 0
26796 lseek(3, 116, SEEK_SET)           = 116
26796 read(3, "# columns: 5\n\t1\t6\t0\t0\t1\n\t2\t6\t0\t0"..., 8191) = 8191
26796 lseek(3, 124, SEEK_SET)           = 124
26796 read(3, "s: 5\n\t1\t6\t0\t0\t1\n\t2\t6\t0\t0\t1\n\t3\t6\t"..., 8191) = 8191
26796 lseek(3, 0, SEEK_SET)             = 0
26796 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
26796 close(3)                          = 0
26796 open("Extended_Molecule", O_RDONLY) = 3
26796 read(3, " # name: nspin\n # type: scalar\n\t"..., 8191) = 8191
26796 lseek(3, -8160, SEEK_CUR)         = 31
26796 read(3, "\t1\n # name: FermiE\n # type: scal"..., 8191) = 8191
26796 lseek(3, -8156, SEEK_CUR)         = 66
26796 read(3, "\t0\n # name: iorb\n # type: matrix"..., 8191) = 8191
26796 mmap(NULL, 425984, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f949d5ad000
26796 lseek(3, -8128, SEEK_CUR)         = 129
26796 read(3, "\t1\t6\t0\t0\t1\n\t2\t6\t0\t0\t1\n\t3\t6\t0\t0\t1"..., 8191) = 8191
26796 lseek(3, -8189, SEEK_CUR)         = 131
26796 read(3, "\t6\t0\t0\t1\n\t2\t6\t0\t0\t1\n\t3\t6\t0\t0\t1\n\t"..., 8191) = 8191
26796 lseek(3, -8189, SEEK_CUR)         = 133
26796 read(3, "\t0\t0\t1\n\t2\t6\t0\t0\t1\n\t3\t6\t0\t0\t1\n\t4\t"..., 8191) = 8191
26796 lseek(3, -8189, SEEK_CUR)         = 135
26796 read(3, "\t0\t1\n\t2\t6\t0\t0\t1\n\t3\t6\t0\t0\t1\n\t4\t6\t"..., 8191) = 8191
26796 lseek(3, -8189, SEEK_CUR)         = 137



Anonymous
Sun 12 Jan 2014 10:05:25 PM UTC, comment #19: 

Still unable to reproduce any problems loading the file provided by the OP. Can you test again with the latest 3.8.0 release?

Mike Miller <mtmiller>
Group Member
Fri 22 Nov 2013 05:17:54 PM UTC, comment #18: 

In regards to comment #7, I was suggesting doing something like this


clear
load Extended_Molecule
save newfile
quit
# start Octave again with strace or whatever profiling tool
load newfile


and see if you see the same performance results with this file created by Octave from the same variables.

Mike Miller <mtmiller>
Group Member
Fri 22 Nov 2013 05:13:23 PM UTC, comment #17: 

Yeah, trying compressed file this time.

(file #29690)

Mike Miller <mtmiller>
Group Member
Fri 22 Nov 2013 05:11:43 PM UTC, comment #16: 

Do we need the complete file to demonstrate the problem?  It looks like the strace output you are showing comes from the beginning of the file.

Does this file contain multiple data elements?  If so, you could split it at the second "# name = ..." line.

Or, you could just split it at an arbitrary point.  It won't load properly, but strace should show the seeks before it fails.

Also, how large is it if you compress it?

And what is the file size limit for attachments to the tracker?  It claims 16MB.

John W. Eaton <jwe>
Group administrator
Fri 22 Nov 2013 05:04:48 PM UTC, comment #15: 

Sounds like the same upload problem I experienced and mentioned in comment #6?

Anonymous
Fri 22 Nov 2013 05:03:19 PM UTC, comment #14: 

It won't take the attachment for me.

Mike Miller <mtmiller>
Group Member
Fri 22 Nov 2013 05:02:16 PM UTC, comment #13: 

I'm attaching the file that the OP sent me via email (3 MB, should be under the file size limit).

But note that I cannot reproduce the reported problem with this file, so I still haven't seen a way to demonstrate the slow I/O performance claimed in this bug report.

Mike Miller <mtmiller>
Group Member
Fri 22 Nov 2013 04:58:55 PM UTC, comment #12: 

Can someone please attach a sample file that demonstrates the problem to this bug report?

John W. Eaton <jwe>
Group administrator
Fri 22 Nov 2013 04:37:46 PM UTC, comment #11: 


That script looks like it only loads the data? I was asking for a full set of commands to load the original file, save it in the correct format, then load the correct-format data. I can guess the commands to do this, but as I'm not an octave user I thought it best to ask for the full set of commands to make sure I was running your test exactly.

Anonymous
Fri 22 Nov 2013 02:24:14 AM UTC, comment #10: 

Sorry for forgetting about this for a few days.

All I run to test is


octave:1> tic; load Extended_Molecule; toc
Elapsed time is 0.13583 seconds.


Here is the command I used from the shell to run the same test under strace, where I see many lseeks as I said earlier, but none that do a reverse seek as reported in an earlier comment.


$ time strace -tt -o Extended_Molecule.trace octave -qfH --eval "load Extended_Molecule"

real        0m0.337s
user        0m0.288s
sys        0m0.040s


Mike Miller <mtmiller>
Group Member
Mon 11 Nov 2013 03:43:28 PM UTC, comment #9: 

Response to comment #7: can you suggest a script to test that out? I'm not an octave user myself.

Response to comment #8:

OS Release is:

% cat /etc/redhat-release
Scientific Linux release 6.4 (Carbon)

Compiler is system default Gnu:

% g++ -v
Using built-in specs.
Target: x86_64-redhat-linux
Configured with: ../configure --prefix=/usr --mandir=/usr/share/man --infodir=/usr/share/info --with-bugurl=http://bugzilla.redhat.com/bugzilla --enable-bootstrap --enable-shared --enable-threads=posix --enable-checking=release --with-system-zlib --enable-__cxa_atexit --disable-libunwind-exceptions --enable-gnu-unique-object --enable-languages=c,c++,objc,obj-c++,java,fortran,ada --enable-java-awt=gtk --disable-dssi --with-java-home=/usr/lib/jvm/java-1.5.0-gcj-1.5.0.0/jre --enable-libgcj-multifile --enable-java-maintainer-mode --with-ecj-jar=/usr/share/java/eclipse-ecj.jar --disable-libjava-multilib --with-ppl --with-cloog --with-tune=generic --with-arch_32=i686 --build=x86_64-redhat-linux
Thread model: posix
gcc version 4.4.7 20120313 (Red Hat 4.4.7-3) (GCC)


Anonymous
Sat 02 Nov 2013 05:50:12 PM UTC, comment #8: 

It might also be relevant which compiler and system libraries are you using. What OS/distro/compiler is this seen with? Octave is using STL iostreams for file reading and writing.

Mike Miller <mtmiller>
Group Member
Sat 02 Nov 2013 05:47:14 PM UTC, comment #7: 

I can't reproduce the reverse seeks with the current development version (hg revision 6b787e274eb1). When the sample file is read into Octave, I see many instances of


lseek(3, 0, SEEK_CUR)


to get the current file offset, but I don't see any reverse seeking and re-reading of data as reported in comment #1, comment #4, and comment #6. The file loads in 0.188 seconds for me.

I also notice that the file is not exactly the same format as one created by Octave, might that make a difference, even though I'm not seeing the same behavior you are? If you load the file, save all of the variables to a new file with Octave, and load this new file do you see the same I/O call behavior?

Mike Miller <mtmiller>
Group Member
Tue 29 Oct 2013 03:51:03 PM UTC, comment #6: 

I have a smaller file which exhibits the same behaviour. The Attached Files option here isn't working for me, so I'll email the sample to the addresses in the cc list of the last comment.

Relevant part of strace output is:

21421 1381762047.573056 stat("Extended_Molecule", {st_mode=S_IFREG|0700, st_size=317268812, ...}) = 0 <0.000021>
21421 1381762047.573153 stat("Extended_Molecule", {st_mode=S_IFREG|0700, st_size=317268812, ...}) = 0 <0.000022>
21421 1381762047.573998 brk(0x2c28000)  = 0x2c28000 <0.000012>
21421 1381762047.574694 open("Extended_Molecule", O_RDONLY) = 3 <0.003623>
21421 1381762047.578384 fstat(3, {st_mode=S_IFREG|0700, st_size=317268812, ...}) = 0 <0.000033>
21421 1381762047.578580 lseek(3, 0, SEEK_SET) = 0 <0.000013>
21421 1381762047.578653 read(3, "# name: ", 8) = 8 <0.001227>
21421 1381762047.580030 lseek(3, 512, SEEK_SET) = 512 <0.000062>
21421 1381762047.580247 read(3, "\n   2   ", 8) = 8 <0.000131>
21421 1381762047.580493 lseek(3, 1024, SEEK_SET) = 1024 <0.000071>
21421 1381762047.580673 read(3, "2   1   ", 8) = 8 <0.000062>
21421 1381762047.580784 lseek(3, 2048, SEEK_SET) = 2048 <0.000014>
21421 1381762047.580841 read(3, " 8   2  ", 8) = 8 <0.000027>
21421 1381762047.580913 lseek(3, 4096, SEEK_SET) = 4096 <0.000013>
21421 1381762047.580968 read(3, "  0   1\n", 8) = 8 <0.000740>
21421 1381762047.581755 lseek(3, 8192, SEEK_SET) = 8192 <0.000012>
21421 1381762047.581807 read(3, " 0   1\n ", 8) = 8 <0.000026>
21421 1381762047.581894 lseek(3, 16384, SEEK_SET) = 16384 <0.000014>
21421 1381762047.581957 read(3, "   1\n  6", 8) = 8 <0.000021>
21421 1381762047.582022 lseek(3, 32768, SEEK_SET) = 32768 <0.000013>
21421 1381762047.582074 read(3, "\n 127   ", 8) = 8 <0.000022>
21421 1381762047.582149 lseek(3, 65536, SEEK_SET) = 65536 <0.000012>
21421 1381762047.582204 read(3, "2   1   ", 8) = 8 <0.000023>
21421 1381762047.582270 lseek(3, 131072, SEEK_SET) = 131072 <0.000012>
21421 1381762047.582324 read(3, "10   2  ", 8) = 8 <0.000528>
21421 1381762047.582904 lseek(3, 262144, SEEK_SET) = 262144 <0.000012>
21421 1381762047.582960 read(3, " 4  -8.5", 8) = 8 <0.000715>
21421 1381762047.583738 lseek(3, 524288, SEEK_SET) = 524288 <0.000016>
21421 1381762047.583796 read(3, "0000E+00", 8) = 8 <0.000625>
21421 1381762047.584484 lseek(3, 1048576, SEEK_SET) = 1048576 <0.000015>
21421 1381762047.584545 read(3, "0.000000", 8) = 8 <0.000622>
21421 1381762047.585224 lseek(3, 2097152, SEEK_SET) = 2097152 <0.000011>
21421 1381762047.585277 read(3, ".0000000", 8) = 8 <0.000544>
21421 1381762047.585864 lseek(3, 4194304, SEEK_SET) = 4194304 <0.000011>
21421 1381762047.585916 read(3, "00000000", 8) = 8 <0.000487>
21421 1381762047.586450 lseek(3, 8388608, SEEK_SET) = 8388608 <0.000010>
21421 1381762047.586501 read(3, "00000E+0", 8) = 8 <0.000512>
21421 1381762047.587066 lseek(3, 16777216, SEEK_SET) = 16777216 <0.000011>
21421 1381762047.587121 read(3, "0   7.84", 8) = 8 <0.000534>
21421 1381762047.587711 lseek(3, 33554432, SEEK_SET) = 33554432 <0.000011>
21421 1381762047.587763 read(3, "E-03   0", 8) = 8 <0.000559>
21421 1381762047.588372 lseek(3, 67108864, SEEK_SET) = 67108864 <0.000011>
21421 1381762047.588423 read(3, "49  1320", 8) = 8 <0.000504>
21421 1381762047.588980 lseek(3, 134217728, SEEK_SET) = 134217728 <0.000011>
21421 1381762047.589033 read(3, "4   0.00", 8) = 8 <0.000521>
21421 1381762047.589597 lseek(3, 268435456, SEEK_SET) = 268435456 <0.000010>
21421 1381762047.589648 read(3, "27  -1.0", 8) = 8 <0.000472>
21421 1381762047.590195 close(3)        = 0 <0.000021>
21421 1381762047.590297 open("Extended_Molecule", O_RDONLY) = 3 <0.000025>
21421 1381762047.590442 read(3, "# name: nspin\n# type: scalar\n   "..., 8191) = 8191 <0.000037>
21421 1381762047.590602 lseek(3, 0, SEEK_SET) = 0 <0.000014>
21421 1381762047.590679 read(3, "# name: nspin\n# type: scalar\n   "..., 8191) = 8191 <0.000032>
21421 1381762047.590776 lseek(3, 0, SEEK_SET) = 0 <0.000013>
21421 1381762047.590852 lseek(3, 116, SEEK_SET) = 116 <0.000017>
21421 1381762047.591019 read(3, " 6480\n# columns: 5\n   1   2   0 "..., 8191) = 8191 <0.000025>
21421 1381762047.591116 lseek(3, 124, SEEK_SET) = 124 <0.000009>
21421 1381762047.591170 read(3, "columns: 5\n   1   2   0   0   1\n"..., 8191) = 8191 <0.000023>
21421 1381762047.591244 lseek(3, 0, SEEK_SET) = 0 <0.000010>
21421 1381762047.591310 read(3, "# name: nspin\n# type: scalar\n   "..., 8191) = 8191 <0.000024>
21421 1381762047.591434 close(3)        = 0 <0.000021>
21421 1381762047.591516 open("Extended_Molecule", O_RDONLY) = 3 <0.000024>
21421 1381762047.591592 read(3, "# name: nspin\n# type: scalar\n   "..., 8191) = 8191 <0.000027>
21421 1381762047.591694 lseek(3, -8162, SEEK_CUR) = 29 <0.000010>
21421 1381762047.591749 read(3, "   1\n# name: FermiE\n# type: scal"..., 8191) = 8191 <0.000026>
21421 1381762047.591905 lseek(3, -8156, SEEK_CUR) = 64 <0.000011>
21421 1381762047.591955 read(3, "    -3.41540\n# name: iorb\n# type"..., 8191) = 8191 <0.000024>
21421 1381762047.592114 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff3ee9d6000 <0.000020>
21421 1381762047.592189 lseek(3, -8120, SEEK_CUR) = 135 <0.000010>
21421 1381762047.592238 read(3, "   1   2   0   0   1\n   1   2   "..., 8191) = 8191 <0.000026>
21421 1381762047.592320 lseek(3, -8187, SEEK_CUR) = 139 <0.000010>
21421 1381762047.592369 read(3, "   2   0   0   1\n   1   2   0   "..., 8191) = 8191 <0.000032>
21421 1381762047.592467 lseek(3, -8187, SEEK_CUR) = 143 <0.000015>
21421 1381762047.592528 read(3, "   0   0   1\n   1   2   0   0   "..., 8191) = 8191 <0.000033>
21421 1381762047.592646 lseek(3, -8187, SEEK_CUR) = 147 <0.000015>
21421 1381762047.592706 read(3, "   0   1\n   1   2   0   0   2\n  "..., 8191) = 8191 <0.000049>
21421 1381762047.592812 lseek(3, -8187, SEEK_CUR) = 151 <0.000010>
21421 1381762047.592860 read(3, "   1\n   1   2   0   0   2\n   1  "..., 8191) = 8191 <0.000025>
21421 1381762047.592938 lseek(3, -8187, SEEK_CUR) = 155 <0.000010>
21421 1381762047.592987 read(3, "\n   1   2   0   0   2\n   1   2  "..., 8191) = 8191 <0.000063>
21421 1381762047.593124 lseek(3, -8186, SEEK_CUR) = 160 <0.000011>
21421 1381762047.593184 read(3, "   2   0   0   2\n   1   2   1   "..., 8191) = 8191 <0.000026>
21421 1381762047.593262 lseek(3, -8187, SEEK_CUR) = 164 <0.000010>
21421 1381762047.593313 read(3, "   0   0   2\n   1   2   1   0   "..., 8191) = 8191 <0.000024>
21421 1381762047.593386 lseek(3, -8187, SEEK_CUR) = 168 <0.000011>

Anonymous
Mon 28 Oct 2013 01:32:53 AM UTC, comment #5: 

I don't see the same set of calls with a text file created by Octave in the current development version. Can you upload the file or a similar text file that shows the behavior to this bug tracker?

Here's what I see:


open("x", O_RDONLY)                     = 3
fstat(3, {st_mode=S_IFREG|0640, st_size=318768434, ...}) = 0
lseek(3, 0, SEEK_SET)                   = 0
read(3, "# Create", 8)                  = 8
lseek(3, 512, SEEK_SET)                 = 512
read(3, "11792406", 8)                  = 8
lseek(3, 1024, SEEK_SET)                = 1024
read(3, "80921890", 8)                  = 8
### cut 37 lines
close(3)                                = 0
open("x", O_RDONLY)                     = 3
read(3, "# Created by Octave 3.7.7+, Sun "..., 8191) = 8191
close(3)                                = 0
open("x", O_RDONLY)                     = 3
read(3, "# Created by Octave 3.7.7+, Sun "..., 8191) = 8191
lseek(3, 0, SEEK_SET)                   = 0
read(3, "# Created by Octave 3.7.7+, Sun "..., 8191) = 8191
lseek(3, 0, SEEK_SET)                   = 0
lseek(3, 116, SEEK_SET)                 = 116
read(3, "ns: 4096\n 0.4302984744815452 0.3"..., 8191) = 8191
lseek(3, 124, SEEK_SET)                 = 124
read(3, "\n 0.4302984744815452 0.306896574"..., 8191) = 8191
lseek(3, 0, SEEK_SET)                   = 0
read(3, "# Created by Octave 3.7.7+, Sun "..., 8191) = 8191
close(3)                                = 0
open("x", O_RDONLY)                     = 3
read(3, "# Created by Octave 3.7.7+, Sun "..., 8191) = 8191
mmap(NULL, 134221824, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f53c74e2000
lseek(3, 0, SEEK_CUR)                   = 8191
lseek(3, 0, SEEK_CUR)                   = 8191
lseek(3, 0, SEEK_CUR)                   = 8191


and so on.

The first 3 opens are for file format detection, the 4th open is when the file is actually read into Octave. While the file is being read, there are about 432 lseeks with zero offset for every read of 8191 bytes. I don't see any lseeks with negative offset.

Mike Miller <mtmiller>
Group Member
Tue 22 Oct 2013 11:02:59 AM UTC, comment #4: 

Answering both questions:

- The input file is text. There was a small script from a user - it looks like they're loading in a text file in order to convert the data to matlab format.

- The version I pulled with Mercurial advertises itself as 3.7.7+. It shows the same odd behaviour as 3.6.4:

32080 open("Extended_Molecule", O_RDONLY) = 3
32080 read(3, "# name: nspin\n# type: scalar\n   "..., 8191) = 8191
32080 lseek(3, -8162, SEEK_CUR)         = 29
32080 read(3, "   1\n# name: FermiE\n# type: scal"..., 8191) = 8191
32080 lseek(3, -8156, SEEK_CUR)         = 64
32080 read(3, "    -3.41540\n# name: iorb\n# type"..., 8191) = 8191
32080 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6390c4b000
32080 lseek(3, -8120, SEEK_CUR)         = 135
32080 read(3, "   1   2   0   0   1\n   1   2   "..., 8191) = 8191
32080 lseek(3, -8187, SEEK_CUR)         = 139
32080 read(3, "   2   0   0   1\n   1   2   0   "..., 8191) = 8191
32080 lseek(3, -8187, SEEK_CUR)         = 143
32080 read(3, "   0   0   1\n   1   2   0   0   "..., 8191) = 8191
32080 lseek(3, -8187, SEEK_CUR)         = 147
32080 read(3, "   0   1\n   1   2   0   0   2\n  "..., 8191) = 8191
32080 lseek(3, -8187, SEEK_CUR)         = 151


Anonymous
Fri 18 Oct 2013 05:57:34 PM UTC, comment #3: 

Also, is the data file an Octave binary file, text file, Matlab file?

Rik <rik5>
Group administrator
Fri 18 Oct 2013 05:51:25 PM UTC, comment #2: 

Can you build from Mercurial sources?  We are just a few weeks away from releasing version 3.8 and it would be nice if this bug wasn't propagated for another cycle.  There have been a number of improvements to fread internally so I believe this has been fixed.  However, if you could build and test it that would be great.

Rik <rik5>
Group administrator
Fri 18 Oct 2013 04:01:21 PM UTC, comment #1: 

Correction: The relevant strace section from the 3.6.4 run is:

21421 1381764984.441148 lseek(3, -8185, SEEK_CUR) = 307121685 <0.000012>
21421 1381764984.441204 read(3, "  6284  -8.3563843509E-04   0.00"..., 8191) = 8191 <0.000024>
21421 1381764984.441280 lseek(3, -8185, SEEK_CUR) = 307121691 <0.000013>
21421 1381764984.441335 read(3, "  -8.3563843509E-04   0.00000000"..., 8191) = 8191 <0.000024>
21421 1381764984.441411 lseek(3, -8172, SEEK_CUR) = 307121710 <0.000013>
21421 1381764984.441467 read(3, "   0.0000000000E+00   7.81841788"..., 8191) = 8191 <0.000027>
21421 1381764984.441545 lseek(3, -8172, SEEK_CUR) = 307121729 <0.000012>
21421 1381764984.441602 read(3, "   7.8184178828E-02   0.00000000"..., 8191) = 8191 <0.000024>
21421 1381764984.441677 lseek(3, -8172, SEEK_CUR) = 307121748 <0.000012>
21421 1381764984.441733 read(3, "   0.0000000000E+00\n   1   615  "..., 8191) = 8191 <0.000025>
21421 1381764984.441811 lseek(3, -8172, SEEK_CUR) = 307121767 <0.000013>
21421 1381764984.441867 read(3, "\n   1   615  6284   5.8303738479"..., 8191) = 8191 <0.000024>
21421 1381764984.441942 lseek(3, -8186, SEEK_CUR) = 307121772 <0.000012>
21421 1381764984.441997 read(3, "   615  6284   5.8303738479E-04 "..., 8191) = 8191 <0.000026

Anonymous
Fri 18 Oct 2013 03:58:03 PM UTC, original submission:  


Running the octave command:

load "Extended_Molecule"

on a large data file (too large to attach) generates excessive I/O and very slow performance on 3.6.4 compared to 3.2.4. Running both versonos through strace shows the cause of the performance issues. On 3.2.4 the relevant part of the strace output shows:

11367 1381761699.667222 open("Extended_Molecule", O_RDONLY) = 3 <0.000016>
11367 1381761699.667283 read(3, "# name: nspin\n# type: scalar\n   "..., 8191) = 8191 <0.000013>
11367 1381761699.667408 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ad4ffa0b000 <0.000007>
11367 1381761699.668171 read(3, "  0   1\n  33   2   0   0   1\n  3"..., 8191) = 8191 <0.000022>
11367 1381761699.668938 read(3, " 0   1\n  63   2   0   0   1\n  63"..., 8191) = 8191 <0.000014>
11367 1381761699.669720 read(3, "0   2\n  95   2   1   0   2\n  95 "..., 8191) = 8191 <0.000015>

[Several hundred more calls to read)

Under 3.6.4 the behaviour is different:

21421 1381762047.574694 open("Extended_Molecule", O_RDONLY) = 3 <0.003623>
21421 1381762047.578384 fstat(3, {st_mode=S_IFREG|0700, st_size=317268812, ...}) = 0 <0.000033>
21421 1381762047.578580 lseek(3, 0, SEEK_SET) = 0 <0.000013>
21421 1381762047.578653 read(3, "# name: ", 8) = 8 <0.001227>
21421 1381762047.580030 lseek(3, 512, SEEK_SET) = 512 <0.000062>
21421 1381762047.580247 read(3, "\n   2   ", 8) = 8 <0.000131>
21421 1381762047.580493 lseek(3, 1024, SEEK_SET) = 1024 <0.000071>
21421 1381762047.580673 read(3, "2   1   ", 8) = 8 <0.000062>
21421 1381762047.580784 lseek(3, 2048, SEEK_SET) = 2048 <0.000014>
21421 1381762047.580841 read(3, " 8   2  ", 8) = 8 <0.000027>
21421 1381762047.580913 lseek(3, 4096, SEEK_SET) = 4096 <0.000013>
21421 1381762047.580968 read(3, "  0   1\n", 8) = 8 <0.000740>
21421 1381762047.581755 lseek(3, 8192, SEEK_SET) = 8192 <0.000012>
21421 1381762047.581807 read(3, " 0   1\n ", 8) = 8 <0.000026>
[Several thousand more calls to read and lseek]

Ie, an approx 8k chunk is read in, and then the file pointer is moved back almost to the start of the 8k chunk. Another 8k is then read, and the file pointer rewound. This continues until the data file is completely read. To read in the whole file involves an 8k read for every 4-6 bytes of data.

Running through gdb to catch the call to lseek shows the following stack:

(gdb) where
#0  0x000000389720ec50 in __lseek_nocancel () from /lib64/libpthread.so.0
#1  0x000000389a26ecbf in std::basic_filebuf<char, std::char_traits<char> >::_M_seek(long, std::_Ios_Seekdir, __mbstate_t) () from /usr/lib64/libstdc++.so.6
#2  0x000000389a26ef4a in std::basic_filebuf<char, std::char_traits<char> >::seekoff(long, std::_Ios_Seekdir, std::_Ios_Openmode) () from /usr/lib64/libstdc++.so.6
#3  0x000000389a275f71 in std::basic_istream<char, std::char_traits<char> >::tellg() () from /usr/lib64/libstdc++.so.6
#4  0x00007ffff5fbd1a5 in octave_read_value<double> (is=...) at lo-utils.cc:257
#5  0x00007ffff6338554 in operator>> (is=..., a=...) at dMatrix.cc:3041
#6  0x00007ffff76c3e03 in octave_matrix::load_ascii (this=0x9664d0, is=...) at ov-re-mat.cc:509
#7  0x00007ffff74fcb76 in octave_value::load_ascii (this=0x7fffffffcd00, is=...) at ov.h:1046
#8  0x00007ffff74fc1da in read_ascii_data (is=..., filename="Extended_Molecule", global=@0x7fffffffcd1f, tc=...,
    count=4) at ls-oct-ascii.cc:285
#9  0x00007ffff74d41ed in do_load (stream=..., orig_fname="Extended_Molecule", format=...,
    flt_fmt=oct_mach_info::flt_fmt_unknown, list_only=false, swap=false, verbose=false, argv=..., argv_idx=2, argc=2,
    nargout=0) at load-save.cc:357
#10 0x00007ffff74d61d5 in Fload (args=..., nargout=0) at load-save.cc:871
#11 0x00007ffff765075d in octave_builtin::do_multi_index_op (this=0x6a73b0, nargout=0, args=..., lvalue_list=0x0)
    at ov-builtin.cc:131
#12 0x00007ffff76503c3 in octave_builtin::subsref (this=0x6a73b0, type="(", idx=std::list = {...}, nargout=0,
    lvalue_list=0x0) at ov-builtin.cc:64
#13 0x00007ffff76502af in octave_builtin::subsref (this=0x6a73b0, type="(", idx=std::list = {...}, nargout=0)
    at ov-builtin.cc:47
#14 0x00007ffff76e64d0 in octave_value::subsref (this=0x7fffffffd7e0, type="(", idx=std::list = {...}, nargout=0)
    at ov.cc:1227
#15 0x00007ffff76e655e in octave_value::subsref (this=0x7fffffffd7e0, type="(", idx=std::list = {...}, nargout=0,
    lvalue_list=0x0) at ov.cc:1238
#16 0x00007ffff776c1b8 in tree_index_expression::rvalue (this=0xac3ef0, nargout=0, lvalue_list=0x0) at pt-idx.cc:414
#17 0x00007ffff776b762 in tree_index_expression::rvalue (this=0xac3ef0, nargout=0) at pt-idx.cc:284
#18 0x00007ffff776c358 in tree_index_expression::rvalue1 (this=0xac3ef0, nargout=0) at pt-idx.cc:425
#19 0x00007ffff7766739 in tree_evaluator::visit_statement (this=0x7ffff7ffc738, stmt=...) at pt-eval.cc:736
#20 0x00007ffff77833aa in tree_statement::accept (this=0x956a80, tw=...) at pt-stmt.cc:151
#21 0x00007ffff7766926 in tree_evaluator::visit_statement_list (this=0x7ffff7ffc738, lst=...) at pt-eval.cc:772
#22 0x00007ffff778375c in tree_statement_list::accept (this=0x9471c0, tw=...) at pt-stmt.cc:215
#23 0x00007ffff76dbfec in octave_user_script::do_multi_index_op (this=0xac4b30, nargout=0, args=...)
    at ov-usr-fcn.cc:138
#24 0x00007ffff752f3ed in source_file (file_name="octave2matlab.m", context="", verbose=false, require_file=true,
    warn_for="octave") at oct-parse.yy:3989
#25 0x00007ffff759c92a in safe_source_file (file_name="octave2matlab.m", context="", verbose=false,
    require_file=true, warn_for="octave") at octave.cc:303
#26 0x00007ffff759d649 in execute_command_line_file (fname="octave2matlab.m") at octave.cc:500
#27 0x00007ffff759f4c4 in octave_main (argc=3, argv=0x7fffffffe1d8, embedded=0) at octave.cc:902
#28 0x0000000000400659 in main (argc=3, argv=0x7fffffffe1d8) at main.c:35

Anonymous

 

(Note: upload size limit is set to 16384 kB, after insertion of the required escape characters.)

Attach Files:
   
   
Comment:
   

Attached Files
file #29690:  Extended_Molecule.gz added by mtmiller (232KiB - application/postscript)

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by jwe (Posted a comment)
  • -email is unavailable- added by mtmiller (Posted a comment)
  • -email is unavailable- added by None (Submitted the item)
  •  

    There are 0 votes so far. Votes easily highlight which items people would like to see resolved in priority, independently of the priority of the item set by tracker managers.

    Only group members can vote.

     

    Follow 8 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2014-02-13 mtmiller Open/ClosedOpen Closed
    2014-01-21 mtmiller Severity3 - Normal 2 - Minor
        StatusWorks For Me Wont Fix
        SummaryExcessive I/O in load function Excessive I/O in load function with g++/libstdc++ 4.4
    2014-01-12 mtmiller StatusNeed Info Works For Me
    2013-11-22 rik5 Carbon-CopyRemoved 72865 -
    2013-11-22 mtmiller Attached File- Added Extended_Molecule.gz, #29690
    2013-10-28 mtmiller StatusNone Need Info

    Back to the top

    Powered by Savane 3.13-d3ae.
    Corresponding source code