Debugging techniques in Elixir - ElixirConf 2016

Show some results in the standard output is the first experience in how to debug your code. What is the next step? Probably, the first answer that you found was: start the observer. After some minutes with an awesome feeling, you asked yourself: What I should look here?
In this talk, you will meet some tools, learn how to debug and profile your system, check crash dump and how to find and deal with the most common cause of failure. More than that, you will understand the concepts behind the reports and the observer tool.

Transcript

2. Debugging techniques in Elixir
3. debug |dēˈbəɡ| the process of identifying and removing errors from computer hardware or software.
4. https://twitter.com/cerealvelocity/status/575826348414885888
5. "Elixir leverages the Erlang VM" Erlang |> Elixir
6. Erlang/OTP has applications to debug and maintain your application
7. What I learned in my journey… • Tools used to debug applications. • When I can use each tool. • How I can analyze the system information. • How I connect to different nodes.
8. @erichkist
9. Sao Paulo - Brazil https://flic.kr/p/fyybDP
10. Organize the tour to catch pokémons and back all of us with life
11. consulting and software engineering Elixir coaching Elixir design review Custom development
13. http://elixir-lang.org/getting-started/introduction.html
14. http://elixir-lang.org/getting-started/introduction.html
15. IO.puts/2
17. iex(1)> IO.puts 1 1 :ok
18. iex(1)> IO.puts {:a, :b} ** (Protocol.UndefinedError) protocol String.Chars not implemented for {:a, :b} (elixir) lib/string/chars.ex:3: String.Chars.impl_for!/1 (elixir) lib/string/chars.ex:17: String.Chars.to_string/ 1 (elixir) lib/io.ex:500: IO.puts/2
19. IO.inspect/2
20. iex(1)> IO.inspect {:a, :b} {:a, :b} {:a, :b} Win! \o/
22. IO.puts vs IO.inspect
23. IO.puts: Chardata strings or lists of characters and strings
24. IO.inspect: Inspect protocol transform any data structure into a readable textual representation
25. http://elixir-lang.org/getting-started/protocols.html
26. “From now on I'll only use inspect"
27. |> Pipeability
28. 1..10 |> Enum.take_random(3) |> Enum.map(&(&1 * 2))
29. list = Enum.take_random(1..10, 3) IO.inspect list list |> Enum.map(&(&1 * 2))
30. 1..10 |> Enum.take_random(3) |> IO.inspect |> Enum.map(&(&1 * 2)) Awesome!!!
31. 1..10 |> Enum.take_random(3) |> IO.inspect |> Enum.map(&(&1 * 2)) |> IO.inspect |> … |> IO.inspect |> … Awesome!!!
32. Inspect.Opts
33. 1..10 |> Enum.take_random(3) |> IO.inspect(label: "list") |> Enum.map(&(&1 * 2)) list: [10, 2, 3] [20, 4, 6] Label
34. 1..10 |> Enum.take_random(3) |> IO.inspect(label: “list") |> Enum.map(&(&1 * 2)) |> IO.inspect(label: “after multiply") |> … |> IO.inspect(label: “after foo") |> … Label
35. https://github.com/elixir-lang/elixir/commit/d6513a7 Label whatyouhide michalmuskala Thank you guys <3 Released?
36. IO.inspect conn Limit
37. %Plug.Conn{adapter: {Plug.Adapters.Cowboy.Conn, :...}, assigns: %{}, before_send: [#Function<0.7834419/1 in Plug.CSRFProtection.call/2>, #Function<4.100417920/1 in Phoenix.Controller.fetch_flash/2>, #Function<0.82590416/1 in Plug.Session.before_send/2>, #Function<1.75806487/1 in Plug.Logger.call/2>, #Function<0.96656268/1 in Phoenix.LiveReloader.before_send_inject_reloader/1>], body_params: %{}, cookies: %{}, halted: false, host: "localhost", method: "GET", owner: #PID<0.381.0>, params: %{}, path_info: [], peer: {{127, 0, 0, 1}, 63732}, port: 4000, private: %{Chat.Router => {[], %{}}, :phoenix_action => :index, :phoenix_controller => Chat.PageController, :phoenix_endpoint => Chat.Endpoint, :phoenix_flash => %{}, :phoenix_format => "html", :phoenix_layout => {Chat.LayoutView, :app}, :phoenix_pipelines => [:browser], :phoenix_route => #Function<1.12450572/1 in Chat.Router.match_route/4>, :phoenix_router => Chat.Router, :phoenix_view => Chat.PageView, :plug_session => %{}, :plug_session_fetch => :done}, query_params: %{}, query_string: "", remote_ip: {127, 0, 0, 1}, req_cookies: %{}, req_headers: [{"host", "localhost:4000"}, {"connection", "keep-alive"}, {"cache-control", "max-age=0"}, {"upgrade-insecure-requests", "1"}, {"user-agent", "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36"}, {"accept", "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8"}, {"accept-encoding", "gzip, deflate, sdch"}, Limit
38. IO.inspect conn, limit: 5 %Plug.Conn{adapter: {Plug.Adapters.Cowboy.Conn, :...}, assigns: %{}, before_send: [#Function<0.7834419/1 in Plug.CSRFProtection.call/2>, #Function<4.100417920/1 in Phoenix.Controller.fetch_flash/ 2>, ...], body_params: %{}, cookies: %{}, ...} Limit
39. http://elixir-lang.org/docs/stable/elixir/Inspect.Opts.html
40. “From now on I’m SURE I'll only use inspect"
41. Code debuging
42. IEx.pry/0 Inspect the state of a particular process
43. defmodule Example do def double(list) do list |> Enum.map(&(&1 * 2)) end end
44. require IEx + IEx.pry
45. require IEx defmodule Example do def double(list) do IEx.pry list |> Enum.map(&(&1 * 2)) end end
46. Things to keep in mind: 1) lexical scope (its bindings and process info) 2) after allowed the pry, shell will be reset 3) a new shell will be started after respawn
48. IEx.pry with Phoenix
49. chrismccord/phoenix_chat_example
51. defmodule Chat.RoomChannel do ... require IEx def handle_in("new:msg", msg, socket) do IEx.pry broadcast! socket, "new:msg", %{user: msg["user"], body: msg["body"]} {:reply, {:ok, %{msg: msg["body"]}}, assign(socket, :user, msg["user"])} end end web/channels/room_channel.ex
52. fail $ mix phoenix.server Cannot pry #PID<0.336.0> at web/channels/ room_channel.ex:44. Is an IEx shell running?
53. $ iex -S mix phoenix.server success
54. IEx.pry with tests
55. $ mix test Cannot pry #PID<0.244.0> at test/ chat_test.exs:7. Is an IEx shell running? fail
56. $ iex -S mix test success
57. It blocks the process Don’t use it in production
58. IEx.pry isn’t a tradicional debugger
59. :debugger Erlang Debugger for debugging and testing
60. iex(1)> :debugger.start() {:ok, #PID<0.87.0>}
61. You can set almost anything in the graphical tool
62. iex(2)> :int.ni(Chat.RoomChannel) {:module, Chat.RoomChannel}
66. It blocks the process Don’t use in production environment
67. Unlike some debuggers, you can’t change all the values of the bound variables…
68. pid, reference, binary, or port values cannot be changed
69. development & production mode
70. Code & Behavior debugging
71. https://flic.kr/p/8k9JhZ
72. Erlang VM
73. Multicore, Schedulers and Reductions
74. Symmetric Multi-Processing SMP takes full advantage of multiple CPU architectures
75. For every core, the BEAM virtual machine starts a thread that runs a scheduler
76. https://hamidreza-s.github.io/erlang/scheduling/real-time/preemptive/migration/2016/02/09/erlang-scheduler- details.html
77. Preemptive and reduction count
78. Scheduler working Queue Scheduler Done
79. Process done Queue Scheduler Done
80. Scheduler runs new process Queue Scheduler Done
81. Scheduler will run the process Process reduction count: 0 Scheduler reduction limit: 500 Scheduler fake values
82. process is running Process reduction count: 123 Scheduler reduction limit: 500 Scheduler fake values
83. process is running Process reduction count: 123 Scheduler reduction limit: 500 Scheduler cheap function fake values
84. process is running Process reduction count: 999 Scheduler reduction limit: 500 Scheduler expensive function fake values
85. Process is preempted Queue Scheduler Done
86. Scheduler working Queue Scheduler Done
87. Scheduler working Queue Scheduler Done
88. :observer Tracing and investigation of distributed systems
89. iex(1)> :observer.start() :ok
90. Common errors
91. CPU bottleneck
94. CPU is very hard to profile
95. The VM does a lot of work unrelated to processes when it comes to scheduling
96. To avoid going to sleep when work is low, the threads that control the Erlang schedulers will do busy looping
98. High reduction count usually means a high amount of CPU usage
104. Memory leak
106. Memory types
107. 3 mistakes to avoid
108. ETS tables are never garbage collected Only removing records manually will reclaim memory
109. Don’t use dynamic atoms Atoms go in a global table and are cached forever!
110. Message queue the most common cause of failure
111. http://learnyousomeerlang.com/the-hitchhikers-guide-to-concurrency
113. Identifying errors
114. Crash Dump Travel machine!
115. erl_crash.dump
116. :observer > File > Examine Crashdump
118. Tracing
119. :et, :dbg, :ttb (:observer) Some tracing modules in the Erlang
129. andytill/erlyberly
131. Connect to a remote node
132. It isn’t hard! but… you may find troubles.
133. module :observer can be not available Releases are self contained packages without unnecessary applications
134. iex(node@remote)1> :observer.start ** (UndefinedFunctionError) undefined function :observer.start/0 (module :observer is not available) :observer.start()
135. :runtime_tools low footprint tracing/debugging tools in a production system
136. def application do [mod: {Chat, []}, applications: [:runtime_tools, …]] end mix.exs
137. server without graphical interface
138. Name your remote node
139. ## Name of the node -sname my_app ## Cookie for distributed erlang -setcookie my_cookie running-config/vm.args
140. Erlang Port Mapper Daemon daemon acts as a name server on all hosts involved in distributed Erlang computations
141. EPMD Port: 4369
142. $ iex --sname my_app@localhost --cookie my_cookie -S mix phoenix.server
143. EPMD Port: 4369 Port: 64722 my_app
144. $ epmd -names epmd: up and running on port 4369 with data: name my_app at port 64722
145. Run :observer in a standalone node to minimize the impact of the system being observed
146. $ iex --sname observer@localhost --cookie my_cookie --hidden -e ":observer.start"
147. EPMD Port: 4369 my_app Port: 64722 :observer Port: 64749
148. $ epmd -names epmd: up and running on port 4369 with data: name observer at port 64749 name my_app at port 64722
150. SSH Port forwarding local EPMD port -> remote EPMD port
151. http://blog.plataformatec.com.br/2016/05/ tracing-and-observing-your-remote-node/
152. SASL System Architecture Support Libraries
153. Redirects supervisor, crash and progress reports to Logger
154. 09:27:51.872 [info] Child Logger.ErrorHandler of Supervisor Logger.Supervisor started Pid: #PID<0.78.0> Start Call: Logger.Watcher.watcher(:error_logger, Logger.ErrorHandler, {true, true, 500}, :link) Restart: :permanent Shutdown: 5000 Type: :worker 09:27:51.884 [info] Application logger started at :nonode@nohost 09:27:52.174 [info] Child Mix.State of Supervisor Mix.Supervisor started Pid: #PID<0.86.0> Start Call: Mix.State.start_link() Restart: :permanent Shutdown: 5000 Type: :worker
155. $ iex --logger-sasl-reports true -S mix
156. def application do [mod: {Chat, []}, applications: [:sasl, …]] end mix.exs
157. Recap!
158. Some tools we can use only for development..
159. System information is different…
160. crash dump is your friend
161. You can run observer (and others tools) locally connected in your remote nodes!
162. Next steps
163. http://erlang.org/doc/applications.html
165. h4cc/awesome-elixir
167. "Measuring your Elixir Application” Talk by Renan Ranelli - Track 2 - 3:30PM
168. https://www.youtube.com/watch?v=4u6c2FNauYE
169. https://www.youtube.com/watch?v=mrKwM9g6baQ
170. https://www.erlang-in-anger.com/
171. Thank you! @erichkist https://speakerdeck.com/erichkist