Crystal 0.22.0 not using previous .o files with LLVM 4.0

[sdogruyol]

OS X 10.12.1
Crystal Version

Crystal 0.22.0 (2017-04-20) LLVM 4.0.0

Test

➜  kemal git:(master) ✗ crystal build --release --stats src/kemal.cr
Parse:                             00:00:00.0007590 (   0.25MB)
Semantic (top level):              00:00:00.3269870 (  36.07MB)
Semantic (new):                    00:00:00.0020600 (  44.07MB)
Semantic (type declarations):      00:00:00.0206440 (  44.07MB)
Semantic (abstract def check):     00:00:00.0011700 (  44.07MB)
Semantic (ivars initializers):     00:00:00.0083290 (  44.07MB)
Semantic (cvars initializers):     00:00:00.0213510 (  44.07MB)
Semantic (main):                   00:00:00.0692010 (  60.07MB)
Semantic (cleanup):                00:00:00.0008920 (  60.07MB)
Semantic (recursive struct check): 00:00:00.0014990 (  60.07MB)
Codegen (crystal):                 00:00:00.1761370 (  60.14MB)
Codegen (bc+obj):                  00:00:06.2013900 (  60.14MB)
Codegen (linking):                 00:00:00.0553900 (  60.14MB)

Codegen (bc+obj):
 - no previous .o files were reused
➜  kemal git:(master) ✗ crystal build --release --stats src/kemal.cr
Parse:                             00:00:00.0008470 (   0.25MB)
Semantic (top level):              00:00:00.2132340 (  36.08MB)
Semantic (new):                    00:00:00.0020160 (  44.08MB)
Semantic (type declarations):      00:00:00.0224410 (  44.08MB)
Semantic (abstract def check):     00:00:00.0016180 (  44.08MB)
Semantic (ivars initializers):     00:00:00.0087780 (  44.08MB)
Semantic (cvars initializers):     00:00:00.0224400 (  44.08MB)
Semantic (main):                   00:00:00.0749190 (  60.08MB)
Semantic (cleanup):                00:00:00.0009240 (  60.08MB)
Semantic (recursive struct check): 00:00:00.0010230 (  60.08MB)
Codegen (crystal):                 00:00:00.1831500 (  60.14MB)
Codegen (bc+obj):                  00:00:07.2118430 (  60.14MB)
Codegen (linking):                 00:00:00.3607290 (  60.14MB)

Codegen (bc+obj):
 - no previous .o files were reused

[luislavena]

It might be related to #4015?

[luislavena]

Can you try using the --no-debug options (from the comments)?

[sdogruyol]

@luislavena it's still the same

➜  kemal git:(master) crystal build --release --stats src/kemal.cr --no-debug
Parse:                             00:00:00.0033540 (   0.25MB)
Semantic (top level):              00:00:00.3551740 (  35.63MB)
Semantic (new):                    00:00:00.0025130 (  35.63MB)
Semantic (type declarations):      00:00:00.0301040 (  43.63MB)
Semantic (abstract def check):     00:00:00.0020200 (  43.63MB)
Semantic (ivars initializers):     00:00:00.0329980 (  43.63MB)
Semantic (cvars initializers):     00:00:00.0101640 (  43.63MB)
Semantic (main):                   00:00:00.1482180 (  59.63MB)
Semantic (cleanup):                00:00:00.0010640 (  59.63MB)
Semantic (recursive struct check): 00:00:00.0014230 (  59.63MB)
Codegen (crystal):                 00:00:00.1238800 (  59.63MB)
Codegen (bc+obj):                  00:00:05.9652400 (  59.63MB)
Codegen (linking):                 00:00:00.2338950 (  59.63MB)

Codegen (bc+obj):
 - no previous .o files were reused
➜  kemal git:(master) ✗ crystal build --release --stats src/kemal.cr --no-debug
Parse:                             00:00:00.0015930 (   0.25MB)
Semantic (top level):              00:00:00.2795280 (  36.07MB)
Semantic (new):                    00:00:00.0020330 (  44.07MB)
Semantic (type declarations):      00:00:00.0186350 (  44.07MB)
Semantic (abstract def check):     00:00:00.0016930 (  44.07MB)
Semantic (ivars initializers):     00:00:00.0074660 (  44.07MB)
Semantic (cvars initializers):     00:00:00.0192180 (  44.07MB)
Semantic (main):                   00:00:00.0666010 (  60.07MB)
Semantic (cleanup):                00:00:00.0007320 (  60.07MB)
Semantic (recursive struct check): 00:00:00.0009970 (  60.07MB)
Codegen (crystal):                 00:00:00.1481130 (  60.14MB)
Codegen (bc+obj):                  00:00:05.7221650 (  60.14MB)
Codegen (linking):                 00:00:00.0888810 (  60.14MB)

Codegen (bc+obj):
 - no previous .o files were reused

[drosehn]

In my testing (Crystal 0.22.0 (2017-04-23) LLVM 4.0.0 on macOS Yosemite 10.10.5), the problem seems to be tied to using --release. If I use --release I get "no previous .o files were reused" (even after compiling multiple times in a row), but if I do not include --release then I get "- 235/236 .o files were reused".

[RX14]

Building with --release will never reuse object files, as the whole program is codegened as 1 unit, producing only 1 object file.

[kostya]

@RX14, yes, but in 0.21.1 second release build of the same code, was much faster, (10times or more), in 0.22 it the same time. so i think 0.21.1 generate the same obj file, but 0.22 generate different obj file every time.

[bcardiff]

I am also experiencing some differences in the .o/.bc generated from build to build.
I've been working a bit in integrating ThinLTO from LLVM and see if contributes for better incremental compilation. But, generating different .o/.bc is not helping.

While I will try to investigate what's happening, if someone has time/wants to collaborate in this issue it will be appreciated.

Maybe is an llvm 4.0 issue? It would be worth to try other llvm versions.

[RX14]

I have an llvm build set up on my desktop, maybe I'll try bisecting.

[bcardiff]

@RX14 Note that I am not saying it is definitely an llvm issue. But everyone in the thread is in llvm 4.0

[RX14]

If it's not an LLVm issue i'll just bisect the compiler :)

[RX14]

It was a crystal issue. First bad commit was 0f85b6e.

Here's the ir diff between 2 runs. The only difference is the macro name in the (debug info?)

diff --git a/tmp/1.ll b/tmp/2.ll
index 4468c82..e75d08f 100644
--- a/tmp/1.ll
+++ b/tmp/2.ll
@@ -980,16 +980,16 @@ target triple = "x86_64-unknown-linux-gnu"
 @"'UInt64'" = private constant { i32, i32, i32, [7 x i8] } { i32 1, i32 6, i32 6, [7 x i8] c"UInt64\00" }
 @"'UInt8'" = private constant { i32, i32, i32, [6 x i8] } { i32 1, i32 5, i32 5, [6 x i8] c"UInt8\00" }
 @"' to (UInt32 | UInt6...'" = private constant { i32, i32, i32, [29 x i8] } { i32 1, i32 28, i32 28, [29 x i8] c" to (UInt32 | UInt64) failed\00" }
-@"', at expanded macro...'" = private constant { i32, i32, i32, [45 x i8] } { i32 1, i32 44, i32 44, [45 x i8] c", at expanded macro: macro_94073737108992:36\00" }
+@"', at expanded macro...'" = private constant { i32, i32, i32, [45 x i8] } { i32 1, i32 44, i32 44, [45 x i8] c", at expanded macro: macro_94014612524544:36\00" }
 @"'Nil'" = private constant { i32, i32, i32, [4 x i8] } { i32 1, i32 3, i32 3, [4 x i8] c"Nil\00" }
 @"' to String failed'" = private constant { i32, i32, i32, [18 x i8] } { i32 1, i32 17, i32 17, [18 x i8] c" to String failed\00" }
-@"', at expanded macro...'.4" = private constant { i32, i32, i32, [45 x i8] } { i32 1, i32 44, i32 44, [45 x i8] c", at expanded macro: macro_94073737108992:37\00" }
+@"', at expanded macro...'.4" = private constant { i32, i32, i32, [45 x i8] } { i32 1, i32 44, i32 44, [45 x i8] c", at expanded macro: macro_94014612524544:37\00" }
 @"Debug::DWARF::AT::DW_AT_low_pc:init" = internal global i1 false
 @"' to UInt64 failed'" = private constant { i32, i32, i32, [18 x i8] } { i32 1, i32 17, i32 17, [18 x i8] c" to UInt64 failed\00" }
-@"', at expanded macro...'.5" = private constant { i32, i32, i32, [45 x i8] } { i32 1, i32 44, i32 44, [45 x i8] c", at expanded macro: macro_94073737108992:39\00" }
+@"', at expanded macro...'.5" = private constant { i32, i32, i32, [45 x i8] } { i32 1, i32 44, i32 44, [45 x i8] c", at expanded macro: macro_94014612524544:39\00" }
 @"Debug::DWARF::AT::DW_AT_high_pc:init" = internal global i1 false
-@"', at expanded macro...'.6" = private constant { i32, i32, i32, [45 x i8] } { i32 1, i32 44, i32 44, [45 x i8] c", at expanded macro: macro_94073737108992:42\00" }
-@"', at expanded macro...'.7" = private constant { i32, i32, i32, [45 x i8] } { i32 1, i32 44, i32 44, [45 x i8] c", at expanded macro: macro_94073737108992:44\00" }
+@"', at expanded macro...'.6" = private constant { i32, i32, i32, [45 x i8] } { i32 1, i32 44, i32 44, [45 x i8] c", at expanded macro: macro_94014612524544:42\00" }
+@"', at expanded macro...'.7" = private constant { i32, i32, i32, [45 x i8] } { i32 1, i32 44, i32 44, [45 x i8] c", at expanded macro: macro_94014612524544:44\00" }
 @"UInt64::MIN:init" = internal global i1 false
 @"'Overflow: UInt64::M...'" = private constant { i32, i32, i32, [27 x i8] } { i32 1, i32 26, i32 26, [27 x i8] c"Overflow: UInt64::MIN / -1\00" }
 @"'Invalid Int32: '" = private constant { i32, i32, i32, [16 x i8] } { i32 1, i32 15, i32 15, [16 x i8] c"Invalid Int32: \00" }

[bcardiff]

But I thought is also happen with --no-debug.

Note that although the macro could differ in it's name, since they are intepreted they should not be present in the .ll / .o. Maybe the name of the macro that expanded appear in the stacktrace, even if --no-debug is present (?)

Can you share the code and build command?

[asterite]

To save you some time, the culprit is this line. It should probably use original_location or something similar.

[mverzilli]

Thanks @RX14 for the research! ❤️

[luislavena]

@asterite could be possible to use a fingerprint/hash of the macro instead of a number? That way if there is no change in the macro, it doesn't produces a difference. 🤔

[bcardiff]

@luislavena the challenge with caching macros is that they are very powerful. They depend on other resources the compiler is unaware.

For this fix, the debug location needed to be the original_location since otherwise it leads to a spurious location and not a file:line the use can access.

[akzhan]

For now second touch src/compiler/crystal.cr && make stats=1 is:

Codegen (bc+obj):
 - 1233/1246 .o files were reused

These modules were not reused:
 - _main (_main.bc)
 - Process (P-rocess.bc)
 - Event::SignalHandler (E-vent5858S-ignalH-andler.bc)
 - Event::SignalChildHandler (E-vent5858S-ignalC-hildH-andler.bc)
 - Crystal::Command (C-rystal5858C-ommand.bc)
 - Crystal::Init (C-rystal5858I-nit.bc)
 - Concurrent::Future(Process::Status) (C-oncurrent5858F-uture40P-rocess5858S-tatus41.bc)
 - Crystal::Compiler (C-rystal5858C-ompiler.bc)
 - Crystal::Config (C-rystal5858C-onfig.bc)
 - Hash(String, Int32) (H-ash40S-tring4432I-nt3241.bc)
 - Crystal::Playground::Server (C-rystal5858P-layground5858S-erver.bc)
 - Crystal::Playground::Session (C-rystal5858P-layground5858S-ession.bc)
 - HTTP::Server (H-T-T-P-5858S-erver.bc)

and third ok.