bugGNU Octave - Bugs: bug #60984, Load function on Windows is...

 
 

bug #60984: Load function on Windows is significantly slower than on Linux

Submitter:  Maxim Smolskij <mithridat>
Submitted:  Wed 28 Jul 2021 07:01:37 PM UTC
   
 
Category:  Performance Severity:  3 - Normal
Priority:  4 Item Group:  Performance
Status:  In Progress Assigned to:  None
Originator Name:  Mithridat Open/Closed:  * Open
Release:  * dev Operating System:  * Microsoft Windows
Fixed Release:  None Planned Release:  None
* Mandatory Fields

Add a New Comment Rich Markup
   

Jump to the original submission

Sat 28 Aug 2021 02:02:23 PM UTC, comment #13: 

Thanks Markus.  I agree that something (3x) is much better than nothing.

Rik <rik5>
Group administrator
Fri 27 Aug 2021 04:30:18 PM UTC, comment #12: 

I almost forgot about this.

While it still isn't as tangy on Windows as it is on Linux, a performance improvement by a factor of about 3 is a step in the right direction.

I pushed a change that sets the locale to C while loading double and single matrices in real and complex in ASCII format here:
https://hg.savannah.gnu.org/hgweb/octave/rev/7c494a811cc3

We can leave this report open in case someone comes up with ideas for further improvements.

Markus Mützel <mmuetzel>
Group administrator
Sat 31 Jul 2021 09:26:16 AM UTC, comment #11: 

I attached Very Sleepy CS as a profiler to versions of Octave with and without the changes from comment #9 while running `load('A.txt')`.
The execution takes notably longer when the profiler is attached. But I hope the results of the two runs are still comparable.
Taking only "valid" contributors from the results (i.e., discarding time spend in "wait" functions), I see the following top contributors without the changes:

setlocale        27.86s        27.86s        4.33%        4.33%        msvcrt        [unknown]        0        0x7fff1cf09bd7
lseeki64        3.60s        3.60s        0.56%        0.56%        msvcrt        [unknown]        0        0x7fff1cefd35c
ReadConsoleOutputW        0.99s        0.99s        0.15%        0.15%        KERNELBASE        [unknown]        0        0x7fff1c4dc188
_cxa_demangle        0.57s        1.21s        0.09%        0.19%        libstdc++-6        [unknown]        0        0x6fc4b665
read        0.41s        0.41s        0.06%        0.06%        msvcrt        [unknown]        0        0x7fff1cefe52b

And with the changes:

setlocale        6.94s        6.94s        1.93%        1.93%        msvcrt        [unknown]        0        0x7fff1cf09bb8
lseeki64        3.76s        3.76s        1.04%        1.04%        msvcrt        [unknown]        0        0x7fff1cefd35c
ReadConsoleOutputW        0.81s        0.81s        0.23%        0.23%        KERNELBASE        [unknown]        0        0x7fff1c4dc188
_cxa_demangle        0.78s        1.94s        0.22%        0.54%        libstdc++-6        [unknown]        0        0x6fc4b680
free        0.41s        0.41s        0.11%        0.11%        msvcrt        [unknown]        0        0x7fff1cef9c9c
malloc        0.31s        0.31s        0.09%        0.09%        msvcrt        [unknown]        0        0x7fff1cef9d40


It looks like `setlocale` is still the top contributor.

The call stacks presented by Very Sleepy CS that end in `setlocale` look the same for both versions. The top of these stacks (35 before and 27 total after the change) looks like this according to Very Sleepy CS:

setlocale        msvcrt        [unknown]        0        0x7fff1cf09c3d
ZSt14__convert_to_vIdEvPKcRT_RSt12_Ios_IostateRKPi        libstdc++-6        [unknown]        0        0x6fd31964
ZNKSt7num_getIcSt19istreambuf_iteratorIcSt11char_traitsIcEEE6do_getES3_S3_RSt8ios_baseRSt12_Ios_IostateRd        libstdc++-6        [unknown]        0        0x6fc95016
ZNSi10_M_extractIdEERSiRT_        libstdc++-6        [unknown]        0        0x6fcb7bce
ZN6octave12rand_poissonIfEEvT_xPS1_        liboctave-8        [unknown]        0        0x6d27456a
ZrsRSiR6Matrix        liboctave-8        [unknown]        0        0x6c9e9a60
ZN13octave_matrix10load_asciiERSi        liboctinterp-9        [unknown]        0        0x6e941f8b
Z14read_text_dataRSiRKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERbR12octave_valuexb        liboctinterp-9        [unknown]        0        0x6ed23898
ZN6octave16load_save_system9load_varsERSiRKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERKNS_16load_save_formatENS_9mach_info12float_formatEbbbRK13string_vectoriii        liboctinterp-9        [unknown]        0        0x6ecf9a97
ZN6octave16load_save_system4loadERK17octave_value_listi        liboctinterp-9        [unknown]        0        0x6ecfcc84
Z5FloadRN6octave11interpreterERK17octave_value_listi        liboctinterp-9        [unknown]        0        0x6ecfd7c5
ZN14octave_builtin7executeERN6octave14tree_evaluatorEiRK17octave_value_list        liboctinterp-9        [unknown]        0        0x6e8c4049
ZN15octave_function4callERN6octave14tree_evaluatorEiRK17octave_value_list        liboctinterp-9        [unknown]        0        0x6e900c4e

Before the change, one of those stacks was attributed the huge majority of the timing ("top" 4 stacks: ~18 s, ~2.5 s, ~1.8 s, ~1.3 s).
After the change, the "top" 3 stacks contributed the majority (~1.4 s, ~1.3 s, ~1.0 s).
The remaining stacks contributed a few 10 to a few 100 ms each.
I couldn't identify the stack that corresponds to the newly added code. That is strange.
Could it be that compiler optimizations are removing that code completely? But then, why are we seeing different timings with and without the change?
Does `std::setlocale` not call `setlocale`?
IIUC, `setlocale` should have been called twice for each read number (i.e., 1000*1000*2 = 2 million times). That's by far more than the number of stacks that the output of Very Sleepy CS shows. I'm only guessing that Very Sleepy CS grouped some of those very many stacks together. It might have (erroneously) included the call with the differing stack into one of these groups.


As the next largest contributor, the top of the call stacks (total of 2 before and after the change) that end in `lseeki64` looks like this:

lseeki64        msvcrt        [unknown]        0        0x7fff1cefd35c
ZNSt12__basic_fileIcE7seekoffExSt12_Ios_Seekdir        libstdc++-6        [unknown]        0        0x6fcdf242
ZNSt13basic_filebufIcSt11char_traitsIcEE7seekoffExSt12_Ios_SeekdirSt13_Ios_Openmode        libstdc++-6        [unknown]        0        0x6fce85f5
ZNSi5tellgEv        libstdc++-6        [unknown]        0        0x6fcb94d5
ZN6octave12rand_poissonIfEEvT_xPS1_        liboctave-8        [unknown]        0        0x6d274451
ZrsRSiR6Matrix        liboctave-8        [unknown]        0        0x6c9e9a60
ZN13octave_matrix10load_asciiERSi        liboctinterp-9        [unknown]        0        0x6e941f8b
Z14read_text_dataRSiRKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERbR12octave_valuexb        liboctinterp-9        [unknown]        0        0x6ed23898
ZN6octave16load_save_system9load_varsERSiRKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERKNS_16load_save_formatENS_9mach_info12float_formatEbbbRK13string_vectoriii        liboctinterp-9        [unknown]        0        0x6ecf9a97
ZN6octave16load_save_system4loadERK17octave_value_listi        liboctinterp-9        [unknown]        0        0x6ecfcc84
Z5FloadRN6octave11interpreterERK17octave_value_listi        liboctinterp-9        [unknown]        0        0x6ecfd7c5
ZN14octave_builtin7executeERN6octave14tree_evaluatorEiRK17octave_value_list        liboctinterp-9        [unknown]        0        0x6e8c4049
ZN15octave_function4callERN6octave14tree_evaluatorEiRK17octave_value_list        liboctinterp-9        [unknown]        0        0x6e900c4e
ZN6octave14tree_evaluator15remove_autoloadERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEES8_        liboctinterp-9        [unknown]        0        0x6e9f43e5

The time attributed to one of those stacks was notably longer than the other (approx. 3.6 s compared to approx. 0.05 s for the other one in both versions).

I'm not sure how `octave::rand_poisson` made it into these stacks. The only command that should have been running while the profiler was attached was `load`. I don't understand how that would call `octave::rand_poisson`. So, I'm not sure how much we can trust these stacks as a whole.


When loading integer numbers in ASCII format, are we reading them as floating point numbers? Afaict, instantiations of `__convert_to_v` are only called when reading `float`, `double`, or `long double` type numbers.

Markus Mützel <mmuetzel>
Group administrator
Fri 30 Jul 2021 08:58:46 PM UTC, comment #10: 

@Markus: This is certainly helpful: ~3X improvement on reading.  My guess is that any eventual solution is going to have to incorporate at least the measures you evaluated for ov-re-mat.cc.  Using 'grep load_ascii' in libinterp/octave-value shows 51 instances.  Not all of them need changing, like ov-scalar.cc since that will always be just a single value, but there are files like ov-base-int.cc for integer matrices which probably do need the change.

This still leaves ~5X improvement to get to Linux timings.  Probably need to run a profiler at that point to see where the delay is.

Rik <rik5>
Group administrator
Fri 30 Jul 2021 08:13:43 PM UTC, comment #9: 

I tried with a similar approach like the one for bug #59704.

Without the change:

>> tst_bug60984

Elapsed time is 0.023623 seconds.
Elapsed time is 1.57969 seconds.
Elapsed time is 14.6429 seconds.
>> tst_bug60984
Elapsed time is 0.00835681 seconds.
Elapsed time is 1.60271 seconds.
Elapsed time is 16.156 seconds.


With the change:

>> tst_bug60984

Elapsed time is 0.00928807 seconds.
Elapsed time is 1.48853 seconds.
Elapsed time is 5.68233 seconds.
>> tst_bug60984
Elapsed time is 0.00902891 seconds.
Elapsed time is 1.4711 seconds.
Elapsed time is 5.67159 seconds.


I'm attaching a diff with the changes I tried.
I was trying to find out if this would also influence the time for writing the file. But that didn't make a huge difference like you can see in the timing.

Reading the files is notably faster. But still a lot slower than the Linux timings.

If we want to do these changes, we should probably add similar ones for double/float and real/complex matrices. Maybe also sparse?


(file #51714)

Markus Mützel <mmuetzel>
Group administrator
Fri 30 Jul 2021 07:31:18 PM UTC, comment #8: 

The suggested fix for bug #59702 was just checked in today.  It might be worth trying the same fix here.

Rik <rik5>
Group administrator
Fri 30 Jul 2021 08:12:45 AM UTC, comment #7: 

If I may make a comment...

Could be the same kind of problem as for
https://savannah.gnu.org/bugs/?59702

Charles Praplan <charprap>
Thu 29 Jul 2021 09:23:08 PM UTC, comment #6: 

Twice as slow for text versus binary, but still only 2 milliseconds difference which isn't much.

It could still be the idea I mentioned in comment #4.

Rik <rik5>
Group administrator
Thu 29 Jul 2021 09:15:18 PM UTC, comment #5: 

комментарий №2:

> I think there may be something weirdly Microsoft-specific here with the encoding of text files.
>
> Assuming you have the file 'A.txt' created, can you try this code on both Linux and Windows?
>


> fid = fopen ('A.txt', 'rb');
> tic; data = fread (fid, Inf, '*char'); toc
> fclose (fid);
>
> fid = fopen ('A.txt', 'rt');
> tic; data2 = fread (fid, Inf, '*char'); toc
> fclose (fid);


>
> Is there a difference in reading a file based on whether it was opened in binary versus text mode?


Got following results:

Windows 10:
Elapsed time is 0.024045 seconds.
Elapsed time is 0.046618 seconds.

Ubuntu 20.04:
Elapsed time is 0.0179679 seconds.
Elapsed time is 0.0186241 seconds.

Maxim Smolskij <mithridat>
Thu 29 Jul 2021 08:19:41 PM UTC, comment #4: 

@jwe: I wonder, then, whether the issue is that we are doing a lot of character-by-character processing versus line-oriented processing (I'm thinking of finding a 'CR' and then having to either peek() or getc()/ungetc() to check whether it is followed by a 'LF'.  On Linux that processing wouldn't be present because as soon as you find a 'LF' you're done.

Rik <rik5>
Group administrator
Thu 29 Jul 2021 06:21:30 PM UTC, comment #3: 

There may be performance differences with opening and reading files in binary vs. text mode but Octave's load function should always open files in binary mode and deal with line endings explicitly.  If I remember correctly, this is necessary because the load function may need to use tell/seek functions to reset the file position and that only works reliably for binary streams.

John W. Eaton <jwe>
Group administrator
Thu 29 Jul 2021 06:00:16 PM UTC, comment #2: 

I think there may be something weirdly Microsoft-specific here with the encoding of text files.

Assuming you have the file 'A.txt' created, can you try this code on both Linux and Windows?


fid = fopen ('A.txt', 'rb');
tic; data = fread (fid, Inf, '*char'); toc
fclose (fid);

fid = fopen ('A.txt', 'rt');
tic; data2 = fread (fid, Inf, '*char'); toc
fclose (fid);


Is there a difference in reading a file based on whether it was opened in binary versus text mode?

Rik <rik5>
Group administrator
Wed 28 Jul 2021 11:48:30 PM UTC, comment #1: 

First, this doesn't seem like a bug report at all. But to answer your questions:

1. Yes, binary vs text mode performance is well known both in Octave and elsewhere. In particular, "save -binary" is much faster to save and load afterwards, so use it unless you have a very strong reason to save as plain text format. Everything else in plain text will bloat for obvious reasons (it needs one byte per digit, so a number like 200 will need 3 bytes in plain text and only 1 in binary; also plain text formats use whitespace between numbers).

2. Re why is something slower on Windows than on Linux, there are too many variables at play and none of them are Octave-specific. Are you running an antivirus on Windows, even just Microsoft Defender? Is Windows running a file search indexing service like it often does? If you can disable file indexing, does your application speed improve?

Please consider the Octave discussion forum in future as well for questions like this.

Close as Invalid since this isn't an Octave bug?

Anonymous
Wed 28 Jul 2021 07:01:37 PM UTC, original submission:  

I ran following script on GNU Octave, version 6.2.0:
tic
A = rand(1000, 1000);
toc

tic
save(‘A.txt’, ‘A’);
toc

tic
B = load(‘A.txt’);
toc

And got following results:

Windows 10:
Elapsed time is 0.010767 seconds.
Elapsed time is 1.90084 seconds.
Elapsed time is 19.3035 seconds.

Ubuntu 20.04:
Elapsed time is 0.011447 seconds.
Elapsed time is 0.636885 seconds.
Elapsed time is 0.873379 seconds.

So, on Windows load function is more than 20 times slower than on Linux (20 seconds vs. 1 second).

For binary files got following results:
Windows 10:
Elapsed time is 0.012146 seconds.
Elapsed time is 0.00397396 seconds.
Elapsed time is 0.0132461 seconds.

Ubuntu 20.04:
Elapsed time is 0.019496 seconds.
Elapsed time is 0.00729489 seconds.
Elapsed time is 0.00489092 seconds.

So, it’s hundreds of times faster than for text files, there are almost equal results for both operation systems and file size decreased from 20 megabytes to 8 megabytes.

Can anyone please express his ideas about such huge advantage of binary files over text files and what Windows delay for text files may be related with? (and can this delay be significantly reduced?)

Maxim Smolskij <mithridat>

 

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

Attach Files:
   
   
Comment:
   

Attached Files
file #51714:  bug609874-load-save-d.diff added by mmuetzel (2KiB - application/octet-stream)

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by mmuetzel (Updated the item)
  • -email is unavailable- added by rik5
  • -email is unavailable- added by charprap (Posted a comment)
  • -email is unavailable- added by jwe (Posted a comment)
  • -email is unavailable- added by rik5 (Posted a comment)
  • -email is unavailable- added by mithridat (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 6 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2021-08-28 rik5 Priority5 - Normal 4
        StatusNeed Info In Progress
    2021-08-27 mmuetzel Release6.2.0 dev
    2021-07-30 mmuetzel Attached File- Added bug609874-load-save-d.diff, #51714
    2021-07-30 rik5 Carbon-Copy- Added mmuetzel
    2021-07-29 rik5 StatusNone Need Info

    Back to the top

    Powered by Savane 3.13-758e.
    Corresponding source code