[Octave-bug-tracker] [bug #40304] Excessive I/O in load function

[anonymous]

URL:
  <http://savannah.gnu.org/bugs/?40304>

                 Summary: Excessive I/O in load function
                 Project: GNU Octave
            Submitted by: None
            Submitted on: Fri 18 Oct 2013 03:58:03 PM UTC
                Category: Octave Function
                Severity: 3 - Normal
                Priority: 5 - Normal
              Item Group: Performance
                  Status: None
             Assigned to: None
         Originator Name: Mike Pacey
        Originator Email: address@hidden
             Open/Closed: Open
         Discussion Lock: Any
                 Release: 3.6.4
        Operating System: GNU/Linux

    _______________________________________________________

Details:


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", address@hidden, 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





    _______________________________________________________

Reply to this item at:

  <http://savannah.gnu.org/bugs/?40304>

_______________________________________________
  Message sent via/by Savannah
  http://savannah.gnu.org/