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

 
 

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

Submitted by:  None
Submitted on:  Fri 18 Oct 2013 03:58:03 PM UTC  
 
Category: Octave FunctionSeverity: 2 - Minor
Priority: 5 - NormalItem Group: Performance
Status: Wont FixAssigned to: None
Originator Name: Mike PaceyOriginator Email: -unavailable-
Open/Closed: ClosedRelease: 3.6.4
Operating System: GNU/Linux

Add a New Comment (Rich MarkupRich Markup):
   

You are not logged in

Please log in, so followups can be emailed to you.

 

(Jump to the original submission 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>
Project 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:

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

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>
Project 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>
Project Member
Fri 22 Nov 2013 05:17:54 PM UTC, comment #18:

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

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

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

Yeah, trying compressed file this time.

(file #29690)

Mike Miller <mtmiller>
Project 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>
Project 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>
Project 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>
Project 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>
Project 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

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.

Mike Miller <mtmiller>
Project 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>
Project 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

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>
Project 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:

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>
Project 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>
Project 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>
Project 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 File(s):
   
   
Comment:
   

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

 

Depends on the following items: None found

Items that depend on this one: None found

 

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

    Do you think this task is very important?
    If so, you can click here to add your encouragement to it.
    This task has 0 encouragements so far.

    Only project members can vote.

     

    Please enter the title of George Orwell's famous dystopian book (it's a date):

     

     

    Follow 8 latest changes.

    Date Changed By Updated Field Previous Value => Replaced By
    Thu 13 Feb 2014 11:25:10 PM UTCmtmillerOpen/ClosedOpen=>Closed
    Tue 21 Jan 2014 06:08:03 AM UTCmtmillerSeverity3 - 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
    Sun 12 Jan 2014 10:05:25 PM UTCmtmillerStatusNeed Info=>Works For Me
    Fri 22 Nov 2013 05:31:18 PM UTCrik5Carbon-CopyRemoved 72865=>-
    Fri 22 Nov 2013 05:13:23 PM UTCmtmillerAttached File-=>Added Extended_Molecule.gz, #29690
    Mon 28 Oct 2013 01:32:53 AM UTCmtmillerStatusNone=>Need Info

    Back to the top


    Powered by Savane 3.1-cleanup