crystal-lang / crystal

The Crystal Programming Language
https://crystal-lang.org
Apache License 2.0
19.47k stars 1.62k forks source link

[Interpreter] Hash#[]?(key) gives incorrect value in interpreter when hash values are classes #12162

Closed cyangle closed 2 years ago

cyangle commented 2 years ago

Bug Report

Below code gives incorrect value with interpreter.

class Action
end

matcher = Hash(String, Action.class).new

class ActionA < Action
end

class ActionB < Action
end

matcher["a"] = ActionA
matcher["b"] = ActionB

pp matcher

pp matcher["a"]
pp matcher["a"]?

Compiled program's output:

{"a" => ActionA, "b" => ActionB}
ActionA
ActionA

Interpreter's output:

{"a" => ActionA, "b" => ActionB}
ActionA
Action

matcher["a"]? should return ActionA instead of Action.

System info:

$ cr -v
Using compiled compiler at /home/chao/git/personal/crystal/.build/crystal
Crystal 1.5.0-dev [ff55fb1bb] (2022-06-22)

LLVM: 10.0.0
Default target: x86_64-pc-linux-gnu

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.4 LTS
Release:        20.04
Codename:       focal

I found this bug while trying to get a Lucky toy app working with the interpreter. I managed to get it running with minor changes to crystal and pg. But I got this runtime error from the Lucky::RouteHandler:

Can't instantiate abstract class Lucky::Action

For details, see https://github.com/crystal-lang/crystal/pull/12141#issuecomment-1166327085

It took me a while to reduce it to this short example. Hopefully we could use the interpreter to debug small Lucky apps once this is fixed.

asterite commented 2 years ago

Reduced a bit more:

class Action
end

class ActionA < Action
end

class ActionB < Action
end

x = ActionA || ActionB
y = x || Nil
p x # ActionA
p y # Action

So no need for Hash. The problem seems to be the union of a virtual class with another type.

asterite commented 2 years ago

I managed to get it running with minor changes to crystal and pg

Could you share what are those changes? Did the interpreter crash or misbehave along the way, so you had to adjust library code to avoid those faulty paths?

Also I just send #12163 to fix this. You can try compiling an interpreter with that PR and see how far you get into interpreting lucky now.

cyangle commented 2 years ago

You can find my git branch here: https://github.com/cyangle/crystal/tree/interpreter It includes 2 bug fix PRs that have not been merged. Specifically, my changes are in this commit: https://github.com/cyangle/crystal/commit/ff4715cc4fb021182e891e7d6a0b8dd981b16390

For pg, you can see the one line change here: https://github.com/cyangle/crystal-pg/commit/0da7b9ba8a26d76b17e34e43b4349db093c88a01 Without it, the interpreter gives this error:

In lib/pg/src/pg/result_set.cr:42:26

 42 | @rows_affected = frame.rows_affected
                       ^----
Error: BUG: missing call receiver by value cast from PQ::Frame+ to PQ::Frame::CommandComplete (Crystal::VirtualType to Crystal::NonGenericClassType)
cyangle commented 2 years ago

With this PR, the interpreter could run the Lucky toy app. All CRUD APIs for User work correctly.

There's something wrong with the debugger when I try to inspect a method:

$ cr i src/toy.cr 
Using compiled compiler at /home/chao/git/personal/crystal/.build/crystal
Listening on http://0.0.0.0:8080
From: expanded macro: setup_call_method:15:3 Api::V1::Users::Show#call:

    10:         begin
    11:   logger.info do
    12:     "user_id: #{id}"
    13:   end
    14:   debugger
 => 15:   json(UserTwin.new(current_user!))
    16: end
    17:       end
    18: 
    19:       __temp_136 = run_after_pipes
    20: 

pry> id
There was a problem expanding macro 'finished'

Called macro defined in macro 'create'

 27 | macro finished

Which expanded to:

 > 1 |       Habitat.create_settings_methods(Lucky::CookieJar)
 > 2 |     
Error: expanding macro

There was a problem expanding macro 'create_settings_methods'

Called macro defined in lib/habitat/src/habitat.cr:239:3

 239 | macro create_settings_methods(type_with_habitat)

Which expanded to:

 >  1 |     
 >  2 | 
 >  3 |     class HabitatSettings
 >  4 |       
 >  5 | 
 >  6 |       
 >  7 |         
 >  8 |         # NOTE: We can't use the macro level `type.resolve.nilable?` here because
 >  9 |         # there's a few declaration types that don't respond to it which would make the logic
 > 10 |         # more complex. Metaclass, and Proc types are the main, but there may be more.
 > 11 |         
 > 12 |           
 > 13 |         
 > 14 | 
 > 15 | 
 > 16 |         
 > 17 | 
 > 18 |         # Use `begin` to catch if the default value raises an exception,
 > 19 |         # then raise a MissingSettingError
 > 20 |         @@on_set : (HTTP::Cookie -> HTTP::Cookie) | ::Nil | Nil 
 > 21 | 
 > 22 | 
 > 23 |         def self.on_set=(value : (HTTP::Cookie -> HTTP::Cookie) | ::Nil)
 > 24 |           
 > 25 |           @@on_set = value
 > 26 |         end
 > 27 | 
 > 28 |         def self.on_set : (HTTP::Cookie -> HTTP::Cookie) | ::Nil
 > 29 |           @@on_set
 > 30 |         end
 > 31 | 
 > 32 |         # Used for checking missing settings on non-nilable types
 > 33 |         # It's advised to use on_set in your apps to ensure
 > 34 |         # the propper type is checked.
 > 35 |         def self.on_set?
 > 36 |           @@on_set
 > 37 |         end
 > 38 |       
 > 39 | 
 > 40 |       # Generates a hash using the provided values
 > 41 |       def self.to_h
 > 42 |         {
 > 43 |           
 > 44 |             "on_set" => on_set,
 > 45 |           
 > 46 |         }
 > 47 |       end
 > 48 |     end
 > 49 |   
Error: can't infer the type of class variable '@@on_set' of Api::V1::Users::Show

Could you add a type annotation like this

    class Api::V1::Users::Show
      @@on_set : Type
    end

replacing `Type` with the expected type of `@@on_set`?

This is a strange error, the @@on_set is a property on internal class HabitatSettings, but the error says @@on_set is also defined in Api::V1::Users::Show. I might be wrong as I'm not familiar with the internals of the framework.

cyangle commented 2 years ago

With a few workarounds, I got Lucky Website running locally with the interpreter. Though the performance is pretty bad, and the rendered side navbar is not the same as it appears on the website. But still, the interpreter currently is somewhat usable.

$ cr i src/website_v2.cr 
Using compiled compiler at /home/chao/git/personal/crystal/.build/crystal

GET / (4b85a597-eb0f-42d5-acea-2ff738a03370)
 ▸ Handled by Home::Index
 ▸ Rendered Home::IndexPage
 ▸ Sent 200 OK (6.56s) (4b85a597-eb0f-42d5-acea-2ff738a03370)

GET / (0cbfcb8a-2906-4c72-8f57-1e6da043995f)
 ▸ Handled by Home::Index
 ▸ Rendered Home::IndexPage
 ▸ Sent 200 OK (6.56s) (0cbfcb8a-2906-4c72-8f57-1e6da043995f)

GET /guides/getting-started/installing (86e5bca7-c5e5-4054-95d5-27d12dba0691)
 ▸ Handled by Guides::GettingStarted::Installing
 ▸ Rendered Guides::ShowPage
 ▸ Sent 200 OK (22.86s) (86e5bca7-c5e5-4054-95d5-27d12dba0691)

GET /guides/database/intro-to-avram-and-orms (c265f308-476c-463c-9ea6-44f5708ca637)
 ▸ Handled by Guides::Database::IntroToAvramAndORMs
 ▸ Rendered Guides::ShowPage
 ▸ Sent 200 OK (19.57s) (c265f308-476c-463c-9ea6-44f5708ca637)

Right now, you can already use the interpreter to debug small Kemal apps.

asterite commented 2 years ago

Wow. 7 seconds to handle a request? Is that with the compiler compiled in release mode?

cyangle commented 2 years ago

So here are the changes I made to the Lucky website to work with the interpreter in case someone wants to try it out.

There was a problem expanding macro 'delegate'

Called macro defined in /home/chao/git/personal/crystal/src/object.cr:1292:3

1292 | macro delegate(*methods, to object)

Which expanded to:

1 |
2 |
3 | def any?(*args, options) 4 | flashes.any?(*args, *options) 5 | end 6 | 7 |
8 | def any?(
args,
options) 9 | flashes.any?(*args, options) do |yield_args| 10 | yield yield_args 11 | end 12 | end 13 |
14 |
15 |
16 |
17 | def each(*args, *options) 18 | flashes.each(args,
options) 19 | end 20 | 21 |
22 | def each(*args, options) 23 | flashes.each(*args, *options) do |yield_args| 24 | yield yield_args 25 | end 26 | end 27 |
28 |
29 |
30 |
31 | def empty?(
args,
options) 32 | flashes.empty?(*args, options) 33 | end 34 | 35 |
36 | def empty?(*args, *options) 37 | flashes.empty?(args,
options) do |yield_args| 38 | yield yield_args 39 | end 40 | end 41 |
42 |
43 |
44 |
Error: BUG: missing upcast_distinct from Tuple(String, String) to String (Crystal::TupleInstanceType to Crystal::NonGenericClassType)


Finally, You'll need to compile crystal compiler with interpreter enabled from my git branch: https://github.com/cyangle/crystal/tree/interpreter2
cyangle commented 2 years ago

Wow. 7 seconds to handle a request? Is that with the compiler compiled in release mode?

The compiler was compiled in debug mode.

asterite commented 2 years ago

But did you compile the interpreter in release mode?

cyangle commented 2 years ago

The interpreter was compiled in debug mode. I'm building it in release mode now to try it out again.

cyangle commented 2 years ago

@asterite The interpreter in release mode is so much better in performance:

$ cr i src/website_v2.cr 
Using compiled compiler at /home/chao/git/personal/crystal/.build/crystal

GET / (5d3e1a80-0a37-4b1c-b424-e2724ec89c1f)
 ▸ Handled by Home::Index
 ▸ Rendered Home::IndexPage
 ▸ Sent 200 OK (162.02ms) (5d3e1a80-0a37-4b1c-b424-e2724ec89c1f)

GET /guides/getting-started/installing (7a2dcf8b-bfcc-4c31-8b3e-064ce3a33113)
 ▸ Handled by Guides::GettingStarted::Installing
 ▸ Rendered Guides::ShowPage
 ▸ Sent 200 OK (594.41ms) (7a2dcf8b-bfcc-4c31-8b3e-064ce3a33113)

GET /guides/database/intro-to-avram-and-orms (75c60141-827e-42d2-81ae-75766af011bf)
 ▸ Handled by Guides::Database::IntroToAvramAndORMs
 ▸ Rendered Guides::ShowPage
 ▸ Sent 200 OK (468.28ms) (75c60141-827e-42d2-81ae-75766af011bf)

It took about 20 minutes to build a release mode compiler on my Linux box though.

asterite commented 2 years ago

Cool! Yes, LLVM will optimize the main interpreter loop with some specific assembly code that's common for interpreters that makes a huge difference.

cyangle commented 2 years ago

The interpreter loads the code much faster, it took around 8 seconds to start lucky website locally on my Linux box.

I hope the core team could spend more time to improve the interpreter as it could improve the developer experience a lot.

CC: @jwoertink

asterite commented 2 years ago

How much time does it take to load it in compiled (non release) mode?

cyangle commented 2 years ago

I was wrong, I got mixed results with different projects.

The interpreted mode might be significantly slower than the compiled mode.

With release mode compiler, it took around 10 seconds to run lucky website in compiled mode and 8 seconds in interpreted mode.

I also tried it with my toy lucky app and the compiled mode is much faster than the interpreted mode.

With release mode compiler, it took about 8 seconds to start my toy app in compiled mode and 12 seconds in interpreted mode.

With debug mode compiler, it took about 17 seconds to start my toy app in compiled mode and 60 seconds in interpreted mode.

I tried each combination multiple times.

The LLVM optimization definitely improves the performance of the interpreter by a lot.

I think the interpreter's performance could be improved more.

Anyway, the interpreter is very close to being able to debug real world applications.

Thanks to the core team and other contributors for making this possible!