Slow performance on Windows

[Joshua Granick]

I remember Haxe compilation being so fast, it was nearly instant.

Over time, I have seen this get slower, but lately, I feel like compile times are really beginning to hurt, such as 6 to 20 second compile times.

It seems like Haxe performs faster on Mac or Linux, could part of the performance difference be related to using Cygwin instead of MSVC for release builds?

Should we be careful about using abstracts, externs, or other features which may be "more expensive" than other Haxe features?

[Simon Krajewski]

Only --times will tell.

Simon

[Jeff Ward]

Macros are ridiculously expensive: https://twitter.com/Jeff__Ward/status/748945664604770304

In the above sample, they run in an interpreter that is 100x slower than compiled neko program.

[Joshua Granick]

Here are some times I am getting:


PiratePig


Windows / Neko

Total time : 4.373s
------------------------------------
filters : 0.424s, 10%
macro execution : 0.585s, 13%
neko generation : 0.706s, 16%
other : 1.092s, 25%
parsing : 0.424s, 10%
typing : 1.142s, 26%

Total time : 4.403s
------------------------------------
filters : 0.453s, 10%
macro execution : 0.583s, 13%
neko generation : 0.796s, 18%
other : 1.049s, 24%
parsing : 0.422s, 10%
typing : 1.101s, 25%


Linux / Neko

Total time : 3.240s
------------------------------------
filters : 0.440s, 14%
macro execution : 0.540s, 17%
neko generation : 0.720s, 22%
other : 0.490s, 15%
parsing : 0.400s, 12%
typing : 0.650s, 20%


Windows / CPP

Total time : 10.501s
------------------------------------
analyzer-simplify-apply : 0.041s, 0%
filters : 0.947s, 9%
macro execution : 0.418s, 4%
other : 7.930s, 76%
parsing : 0.331s, 3%
typing : 0.835s, 8%

Total time : 6.628s
------------------------------------
analyzer-simplify-apply : 0.041s, 1%
filters : 0.983s, 15%
macro execution : 0.422s, 6%
other : 4.034s, 61%
parsing : 0.333s, 5%
typing : 0.815s, 12%


Linux / CPP

Total time : 3.930s
------------------------------------
analyzer-simplify-apply : 0.060s, 2%
filters : 1.050s, 27%
macro execution : 0.500s, 13%
other : 1.350s, 34%
parsing : 0.370s, 9%
typing : 0.600s, 15%


Windows / JS

Total time : 3.798s
------------------------------------
filters : 0.320s, 8%
generate js : 0.212s, 6%
macro execution : 0.566s, 15%
other : 0.023s, 1%
parsing : 0.402s, 11%
typing : 2.275s, 60%

Total time : 2.596s
------------------------------------
filters : 0.315s, 12%
generate js : 0.179s, 7%
macro execution : 0.606s, 23%
other : 0.021s, 1%
parsing : 0.411s, 16%
typing : 1.064s, 41%


Linux / JS

Total time : 1.670s
------------------------------------
filters : 0.350s, 21%
generate js : 0.050s, 3%
macro execution : 0.460s, 28%
other : 0.020s, 1%
parsing : 0.460s, 28%
typing : 0.330s, 20%


I am running this test natively on Windows, and in a Linux VM on the same
machine for consistency. I know that Linux tends to handle programs faster
than Windows in general, but I'm not sure that's the only explanation.
This is the same code, same OpenFL, same Haxe release (3.2.1)

Current development builds on Windows seem a bit slower (like 5.1s instead
of 4.4 for Neko)

Does anyone have MSVC versions of Haxe built (to compare)?

--
Using Opera's mail client: http://www.opera.com/mail/

[Tarwin Stroh-Spijer]

What is "other" ? On Windows CPP that seems to take most of the extra time, 8 vs 4 seconds.

Tarwin Stroh-Spijer
_______________________

phone: +1 650 842 0920

Developer at Fanplayr Inc. (Palo Alto)

Original at Touch My Pixel (touchmypixel.com)
_______________________

--
To post to this group haxe...@googlegroups.com
http://groups.google.com/group/haxelang?hl=en
---You received this message because you are subscribed to the Google Groups "Haxe" group.

For more options, visit https://groups.google.com/d/optout.

[Simon Krajewski]

Could you post the --times with the development build too? They are a
bit more detailed now and should have less "other".

Simon

[Joshua Granick]

Haxe 3.3.0 (git build development @ 060f31e)

Windows / Neko

name     | time(s) |   % |     # | info

----------------------------------

analyzer |   0.733 |  15 | 89406 |

filters  |   0.449 |   9 |     1 |

generate |   1.018 |  20 |     1 |

  neko   |   1.018 |  20 |     1 |

macro    |   0.445 |   9 |   237 |

other    |   1.022 |  20 |     1 |

parsing  |   0.370 |   7 |   677 |

typing   |   0.985 |  20 |  3136 |

----------------------------------

total    |   5.023 | 100 |     0 |

name     | time(s) |   % |     # | info

----------------------------------

analyzer |   0.712 |  15 | 89406 |

filters  |   0.454 |   9 |     1 |

generate |   0.992 |  20 |     1 |

  neko   |   0.992 |  20 |     1 |

macro    |   0.410 |   8 |   237 |

other    |   0.952 |  20 |     1 |

parsing  |   0.341 |   7 |   677 |

typing   |   0.987 |  20 |  3136 |

----------------------------------

total    |   4.848 | 100 |     0 |

Windows / CPP

name     | time(s) |   % |     # | info

----------------------------------

analyzer |   0.642 |   4 | 87840 |

filters  |   0.393 |   3 |     1 |

generate |  11.857 |  76 |     1 |

  cpp    |  11.857 |  76 |     1 |

macro    |   0.370 |   2 |   237 |

other    |   1.140 |   7 |     1 |

parsing  |   0.348 |   2 |   692 |

typing   |   0.924 |   6 |  3391 |

----------------------------------

total    |  15.676 | 100 |     0 |

name     | time(s) |   % |     # | info

----------------------------------

analyzer |   0.668 |   9 | 87840 |

filters  |   0.397 |   5 |     1 |

generate |   3.583 |  48 |     1 |

  cpp    |   3.583 |  48 |     1 |

macro    |   0.363 |   5 |   237 |

other    |   1.126 |  15 |     1 |

parsing  |   0.354 |   5 |   692 |

typing   |   0.936 |  13 |  3391 |

----------------------------------

total    |   7.428 | 100 |     0 |

Windows / JS

name     | time(s) |   % |     # | info

----------------------------------

analyzer |   0.489 |  14 | 80294 |

filters  |   0.468 |  14 |     1 |

generate |   0.205 |   6 |     1 |

  js     |   0.205 |   6 |     1 |

macro    |   0.557 |  16 |   223 |

other    |   0.021 |   1 |     1 |

parsing  |   0.430 |  13 |   968 |

typing   |   1.263 |  37 |   159 |

----------------------------------

total    |   3.433 | 100 |     0 |

name     | time(s) |   % |     # | info

----------------------------------

analyzer |   0.497 |  14 | 80294 |

filters  |   0.458 |  13 |     1 |

generate |   0.210 |   6 |     1 |

  js     |   0.210 |   6 |     1 |

macro    |   0.555 |  16 |   223 |

other    |   0.021 |   1 |     1 |

parsing  |   0.440 |  13 |   968 |

typing   |   1.302 |  37 |   159 |

----------------------------------

total    |   3.482 | 100 |     0 |

[Hugh]

I don't think such a dramatic difference in times would be to do with CPU usage, unless there is some optimization flags that have not been properly activated when generating the exe.

Which would then leave IO.  Are running your files locally on a SSD?  If you have a linux VM, it is possible it is using a virtual file system which has better buffering than a local HD filesystem or network access.

Hugh

[Joshua Granick]

I ran the tests on a 2016 Lenovo ThinkPad X1 Yoga, with an i7 6600U processor and SSD.

The VM is an Ubuntu install in VMWare Workstation, running over the same Windows 10 install

Does anyone think MSVC would create a faster binary? Something else?

[Cauê Waneck]

Maybe it's a 32-bit vs 64-bit issue?

[Hugh]

I'm still suspecting IO if it is only the one area (gen cpp) that is slow.  Maybe ocaml has different libraries on windows.

Do you have any unmapped (or external) drives/paths in your class path?

Do you think it is to do with resource size?  Does changing resource embedding change things?

Are there any unusually large files generated?

You may be able to do something like:

wc `find bin/windows -name "*.cpp"` | sort

or do this on linux - the files should be the same.

I probably need to do some native profiling.  Working out which sort of projects are slow would be a good start.

[Joshua Granick]

Is this relevant, or too old?

https://caml.inria.fr/mantis/print_bug_page.php?bug_id=5201

I am reading that OCaml (correct me if I am wrong) is unofficially ported to Windows, and has compatibility overhead

[Joshua Granick]

There are no external drives, I don't (believe) there are any embedded resources

The generated HXML is pretty normal

-main ApplicationMain
-cp D:/Development/Haxe/openfl
-D openfl=3.3.2
-cp D:/Development/Haxe/lime
-D lime=2.6.1
-cp D:/Development/Haxe/actuate
-D actuate=1.8.6
-cp Source
-D lime-openal
-D openfl-next
-D tools=2.6.1
-D lime-cairo
-D no-compilation
-D lime-opengl
-D native
-D lime-native
-D lime-curl
-D openfl-native
-D windows
-D desktop
--remap flash:openfl
-cp Export/windows/cpp/haxe
-cpp Export/windows/cpp/obj
--macro keep("piratepig.PiratePig")

On the CPP front, there is actually a file that is 908 KB (ArrayBufferView), perhaps a heavy amount of inlining, though --no-inline didn't make much of a difference in times -- this file actually got bigger.

On Thu, 27 Oct 2016 21:31:58 -0700, Hugh <game...@gmail.com> wrote:

[Tarwin Stroh-Spijer]

Could it have something to do with Windows doing some kind of caching? As in caching before it hits the drive, that Linux isn't doing? I think it does do something like this ... although not sure. It's to speed things up ... but maybe doing weird things here?

[sorry really don't know much but hopefully a very non-low-level view helps?]

Tarwin Stroh-Spijer
_______________________

phone: +1 650 842 0920

Developer at Fanplayr Inc. (Palo Alto)

Original at Touch My Pixel (touchmypixel.com)
_______________________

[Joshua Granick]

I tried to build from source, but it crashed

Perhaps this could be put behind a define:

https://github.com/HaxeFoundation/haxe/blob/bea775d4f3318dd421536ae77cf811f1cbd0e8aa/src/generators/gencommon.ml#L141

Similar to "analyzer-times"

https://github.com/HaxeFoundation/haxe/blob/bea775d4f3318dd421536ae77cf811f1cbd0e8aa/src/optimization/analyzerConfig.ml#L95

I'm interested in comparing the performance of this function

https://github.com/HaxeFoundation/haxe/blob/bea775d4f3318dd421536ae77cf811f1cbd0e8aa/src/generators/gencommon.ml#L871

--