critical poor performances within all loops (repeat, while, for, foreach) on OSX since a while (x86_64 & M1/M2/M3)

[alaingdl]

⚠️ test_loops.pro.txt (just rename it into test_loops.pro)

Hi

The problem "discovered" on M2 processors + OSX is in fact general on OSX, including intel x86_64

(see also : #1755 #1498 )

No relation to OpenMP so far

On OSX, GDL is now compiled with Clang.
I succeed to compile an old version of GDL with GCC.
Same kind of bad preformances :(

best regards

Alain

*** My laptop (u2204 old cpu, last GDL)

GDL> .r test_loops.pro
% Compiled module: TEST_LOOP_REPEAT.
% Compiled module: TEST_LOOP_WHILE.
% Compiled module: TEST_LOOP_FOR.
% Compiled module: TEST_LOOP_FOREACH.
% Compiled module: TEST_LOOPS.
GDL> TEST_LOOPS
% Time elapsed : 0.030267000 seconds.
% Time elapsed : 0.021615982 seconds.
% Time elapsed : 0.0067281723 seconds.
% Time elapsed : 0.0094060898 seconds.
GDL> TEST_LOOPS
% Time elapsed : 0.0084998608 seconds.
% Time elapsed : 0.011459112 seconds.
% Time elapsed : 0.0052161217 seconds.
% Time elapsed : 0.010531902 seconds.

IDL 8.8

IDL> TEST_LOOPS 
% Time elapsed: 0.031649828 seconds.
% Time elapsed: 0.022933960 seconds.
% Time elapsed: 0.0098700523 seconds.
% Time elapsed: 0.0065758228 seconds.
IDL> TEST_LOOPS
% Time elapsed: 0.019623041 seconds.
% Time elapsed: 0.011369944 seconds.
% Time elapsed: 0.0034470558 seconds.
% Time elapsed: 0.0049750805 seconds.

*** a very good (16 cores) OSX with x86_64 proc (OSX 12.3.1; 16 cores)

GDL> TEST_LOOPS
% Time elapsed : 1.2516088 seconds.
% Time elapsed : 1.3307161 seconds.
% Time elapsed : 0.63178301 seconds.
% Time elapsed : 1.4110520 seconds.
GDL> TEST_LOOPS
% Time elapsed : 1.2708800 seconds.
% Time elapsed : 1.3496850 seconds.
% Time elapsed : 0.62935615 seconds.
% Time elapsed : 1.3826480 seconds.

IDL 8.5

IDL> TEST_LOOPS 
% Time elapsed: 0.0055260658 seconds.
% Time elapsed: 0.0052649975 seconds.
% Time elapsed: 0.0030848980 seconds.
% Time elapsed: 0.0047471523 seconds.
IDL> TEST_LOOPS
% Time elapsed: 0.0055871010 seconds.
% Time elapsed: 0.0052540302 seconds.
% Time elapsed: 0.0031099319 seconds.
% Time elapsed: 0.0043449402 seconds.

[alaingdl]

Good new ! Following a discussion here :
https://www.reddit.com/r/cpp/comments/13n3tjt/i_find_its_not_possible_to_do_serious_cc_coding/?rdt=61636

On OSX, with :

cmake .. -DCMAKE_CXX_FLAGS="-fsanitize=address" -DREADLINEDIR=/usr/local/opt/readline/ -DOPENMP=OFF -DHDF=OFF 
``

I got : 

GDL> TEST_LOOPS
% Time elapsed : 0.031697989 seconds.
% Time elapsed : 0.033257008 seconds.
% Time elapsed : 0.017196894 seconds.
% Time elapsed : 0.031798124 seconds.

[GillesDuvert]

@alaingdl very good find! But then with the fsanitize=address flag set, at exit the program GDL should report a list of leaks. And, it should run slower than without the fsanitize option since asan adds tests and make it slower ?

[alaingdl]

I currently don't know exactly what is this flag for and the side effects, it was very important for me to break the bottleneck with OSX. I suspect we need to carefully audit the code to avoid to have to use this flag (I suspect the order of some include)

My colleague tested today on his Mac, was take 1h30 last week is now few minutes.

[alaingdl]

test_grib does have a problem ... very interesting !

GDL> test_grib
% Compiled module: TEST_GRIB.
=================================================================
==13077==ERROR: AddressSanitizer: global-buffer-overflow on address 0x00010af8e708 at pc 0x000109b7119e bp 0x7ff7b82fbdd0 sp 0x7ff7b82fbdc8
READ of size 4 at 0x00010af8e708 thread T0
    #0 0x109b7119d in lib::grib_open_file_fun(EnvT*)+0x67d (gdl:x86_64+0x101f7419d)
    #1 0x10a7a157d in FCALL_LIB_RETNEWNode::Eval()+0x9d (gdl:x86_64+0x102ba457d)
    #2 0x10a7596f6 in ASSIGN_REPLACENode::Run()+0x66 (gdl:x86_64+0x102b5c6f6)
    #3 0x107ce7584 in GDLInterpreter::statement(ProgNode*)+0x4e4 (gdl:x86_64+0x1000ea584)
    #4 0x107cf09fc in GDLInterpreter::execute(ProgNode*)+0x6c (gdl:x86_64+0x1000f39fc)
    #5 0x109515328 in lib::execute_fun(EnvT*)+0x1748 (gdl:x86_64+0x101918328)
    #6 0x10a7a3bd5 in FCALL_LIBNode::Eval()+0xa5 (gdl:x86_64+0x102ba6bd5)
    #7 0x10a7783a2 in BinaryExprNC::AdjustTypesNCNull(Guard<BaseGDL>&, BaseGDL*&, Guard<BaseGDL>&, BaseGDL*&)+0xd2 (gdl:x86_64+0x102b7b3a2)
    #8 0x10a78d267 in EQ_OPNCNode::Eval()+0x137 (gdl:x86_64+0x102b90267)
    #9 0x10a77ec85 in LOG_NEGNode::Eval()+0x55 (gdl:x86_64+0x102b81c85)
    #10 0x10a7596f6 in ASSIGN_REPLACENode::Run()+0x66 (gdl:x86_64+0x102b5c6f6)
    #11 0x107ce73b9 in GDLInterpreter::statement(ProgNode*)+0x319 (gdl:x86_64+0x1000ea3b9)
    #12 0x107cf141c in GDLInterpreter::call_pro(ProgNode*)+0x3c (gdl:x86_64+0x1000f441c)
    #13 0x10a75a9b8 in PCALLNode::Run()+0x1b8 (gdl:x86_64+0x102b5d9b8)
    #14 0x107ce73b9 in GDLInterpreter::statement(ProgNode*)+0x319 (gdl:x86_64+0x1000ea3b9)
    #15 0x107ce705c in GDLInterpreter::interactive(ProgNode*)+0x3c (gdl:x86_64+0x1000ea05c)
    #16 0x1097668e9 in DInterpreter::ExecuteLine(std::__1::basic_istream<char, std::__1::char_traits<char> >*, unsigned long long)+0x40b9 (gdl:x86_64+0x101b698e9)
    #17 0x10977a259 in DInterpreter::InterpreterLoop(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > >&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)+0x1979 (gdl:x86_64+0x101b7d259)
    #18 0x10aaf285a in main+0xa9ba (gdl:x86_64+0x102ef585a)
    #19 0x11ac4151d in start+0x1cd (dyld:x86_64+0x551d)

0x00010af8e708 is located 56 bytes to the left of global variable 'SysVar::trueIx' defined in '/Users/coulais/GDL/gdl-1.0.4git240227compilo/src/initsysvar.cpp:60:16' (0x10af8e740) of size 4
0x00010af8e708 is located 24 bytes to the left of global variable 'SysVar::nullIx' defined in '/Users/coulais/GDL/gdl-1.0.4git240227compilo/src/initsysvar.cpp:60:8' (0x10af8e720) of size 4
0x00010af8e708 is located 16 bytes to the right of global variable 'lib::GribFileList' defined in '/Users/coulais/GDL/gdl-1.0.4git240227compilo/src/grib.cpp:42:21' (0x10af8e6e0) of size 24
SUMMARY: AddressSanitizer: global-buffer-overflow (gdl:x86_64+0x101f7419d) in lib::grib_open_file_fun(EnvT*)+0x67d
Shadow bytes around the buggy address:
  0x1000215f1c90: 04 f9 f9 f9 04 f9 f9 f9 01 f9 f9 f9 01 f9 f9 f9
  0x1000215f1ca0: 01 f9 f9 f9 04 f9 f9 f9 00 00 00 f9 f9 f9 f9 f9
  0x1000215f1cb0: 00 00 00 f9 f9 f9 f9 f9 04 f9 f9 f9 00 00 00 f9
  0x1000215f1cc0: f9 f9 f9 f9 00 00 00 f9 f9 f9 f9 f9 00 00 00 f9
  0x1000215f1cd0: f9 f9 f9 f9 00 00 00 f9 f9 f9 f9 f9 00 00 00 f9
=>0x1000215f1ce0: f9[f9]f9 f9 04 f9 f9 f9 04 f9 f9 f9 04 f9 f9 f9
  0x1000215f1cf0: 04 f9 f9 f9 04 f9 f9 f9 04 f9 f9 f9 04 f9 f9 f9
  0x1000215f1d00: 04 f9 f9 f9 04 f9 f9 f9 04 f9 f9 f9 04 f9 f9 f9
  0x1000215f1d10: 04 f9 f9 f9 04 f9 f9 f9 04 f9 f9 f9 04 f9 f9 f9
  0x1000215f1d20: 04 f9 f9 f9 04 f9 f9 f9 04 f9 f9 f9 04 f9 f9 f9
  0x1000215f1d30: 04 f9 f9 f9 04 f9 f9 f9 04 f9 f9 f9 04 f9 f9 f9
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==13077==ABORTING
Abort trap: 6

[GillesDuvert]

this is something also reported by Valgrind, as fsanitize (lsan) and valgrind are tools to detect memory leaks etc:

GDL> test_grib
% Compiled module: TEST_GRIB.
% TEST_GRIB: opening example.grib...
% TEST_GRIB: number of messages in file:        6
% TEST_GRIB: getting message from file...
% TEST_GRIB: closing file...
% TEST_GRIB: size of ,,numberOfPointsAlongAParallel'' array:            1
% TEST_GRIB: size of ,,values'' array:          441
% TEST_GRIB: trying to get a string key ,,discipline''...
DISC            LONG      =            0
% TEST_GRIB: retrieving ,,values''...
DATA            DOUBLE    = Array[441]
% TEST_GRIB: retrieving ,,numberOfPointsAlongAParallel''...
DATA            LONG      =           21
% TEST_GRIB: retrieving data together with lat/lon arrays using gribapi_get_data...
LATS            DOUBLE    = Array[441]
LONS            DOUBLE    = Array[441]
DATA            DOUBLE    = Array[441]
==3244798== Conditional jump or move depends on uninitialised value(s)
==3244798==    at 0x119332B: lib::contour_call::applyGraphics(EnvT*, GDLGStream*) (in /usr/local/bin/gdl)
==3244798==    by 0x11DDA22: lib::plotting_routine_call::call(EnvT*, unsigned long long) (in /usr/local/bin/gdl)
==3244798==    by 0x118F018: lib::contour(EnvT*) (in /usr/local/bin/gdl)
==3244798==    by 0x11E94C8: PCALL_LIBNode::Run() (in /usr/local/bin/gdl)
==3244798==    by 0x6B60DF: GDLInterpreter::statement(ProgNode*) (in /usr/local/bin/gdl)
==3244798==    by 0x6B74F7: GDLInterpreter::call_pro(ProgNode*) (in /usr/local/bin/gdl)
==3244798==    by 0x11ED0D0: PCALLNode::Run() (in /usr/local/bin/gdl)
==3244798==    by 0x6B60DF: GDLInterpreter::statement(ProgNode*) (in /usr/local/bin/gdl)
==3244798==    by 0x6B6607: GDLInterpreter::interactive(ProgNode*) (in /usr/local/bin/gdl)
==3244798==    by 0xCF51A1: DInterpreter::ExecuteLine(std::istream*, unsigned long long) (in /usr/local/bin/gdl)
==3244798==    by 0xCF630C: DInterpreter::InterpreterLoop(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) (in /usr/local/bin/gdl)
==3244798==    by 0x676EA2: main (in /usr/local/bin/gdl)
==3244798== 
% TEST_GRIB: clearing message from memory...

[GillesDuvert]

fsanitize is just a doctor, as Valgrind. However, as it replaces the memory allocation code by its own, and it was suggested in #1635 that the slowness could come from allocation of objects, perhaps this replacement is beneficial.
Besides, our objects allocate their data storage through system or Eigen:: memory allocators (for alignment purposes that may well be obsolete) so the situation is not clear.

[GillesDuvert]

@alaingdl under linux there is abolutely no difference in the list of memory leaks (using #1762 to get clearer outputs, and -fsanitize=address) between

gdl
exit

and

gdl
test_loops
exit

to be tried on OSX of course.

[GillesDuvert]

Solved