19 Oct 2016
Last week a worker at my job written in Nodejs v0.10 started to fail. At some point the worker would consume 100% of CPU and gradually would increase the memory usage as well. That job was been forced to stop once all the memory available was consumed.
Basically I had two approaches available to find out what was causing the problem.
- Put
console.log every place and find where in my code was the last time executed before getting stuck with 100% of CPU usage.
- Do it right and profile the application to find out properly based in statistics about the running process how much CPU each part was consuming.
Even console.log been a common approach for many simple cases. The profile is the best option for this kind of problem.
So this is the flow I followed to find out the problem:
- Start the app with enabled profile
node --prof index.js.
- In other shell window run
top to monitor when the process get 100% CPU usage.
- Once the process get in high CPU usage stop it.
- The profile will have created
v8.log file.
- In node v0.10 has not a built in tool to process this file. Because of that install one with
npm -g install tick.
- Execute
node-tick-processor and it will print the explained results about the profile log v8-profile-cpu-100-usage.txt.
Looking the [Bottom up (heavy) profile] section I could find out the module causing the 100% CPU usage.
[Bottom up (heavy) profile]:
Note: percentage shows a share of a particular caller in the total
amount of its parent calls.
Callers occupying less than 2.0% are not shown.
ticks parent name
15924 71.2% /opt/node-v0.10.31-linux-x64/bin/node
7742 48.6% Function: ~derez /src/node_modules/cycle/cycle.js:46
7739 100.0% Function: ~derez /src/node_modules/cycle/cycle.js:46
7739 100.0% Function: ~derez /src/node_modules/cycle/cycle.js:46
7739 100.0% Function: ~derez /src/node_modules/cycle/cycle.js:46
7739 100.0% Function: ~derez /src/node_modules/cycle/cycle.js:46
As we can see the cycle is the guilty one. Cycle is a module used to encode and decode JSON data to Javascript. So we know already probably is a JS object been parsed to JSON string. And I would guess this JS object has circular reference and that is why is getting 100% CPU usage without stop until consume all the memory available.
But that was part of the problem. We know who is the responsible. But who is calling that function?
Looking into the [Top down (heavy) profile] I find out that winston module is the one using the cycle. Winston is a library for logging. So are suspicion was right. Probably is a JS object been saved to the log.
[Top down (heavy) profile]:
Note: callees occupying less than 0.1% are not shown.
inclusive self name
ticks total ticks total
18799 84.0% 0 0.0% LazyCompile: ~processImmediate timers.js:335
18767 83.9% 0 0.0% LazyCompile: ~lib$rsvp$asap$$flush /src/node_modules/rsvp/dist/rsvp.js:1193
18747 83.8% 0 0.0% LazyCompile: ~lib$rsvp$$internal$$publishRejection /src/node_modules/rsvp/dist/rsvp.js:957
18747 83.8% 0 0.0% LazyCompile: ~lib$rsvp$$internal$$publish /src/node_modules/rsvp/dist/rsvp.js:1002
18747 83.8% 0 0.0% LazyCompile: ~lib$rsvp$$internal$$invokeCallback /src/node_modules/rsvp/dist/rsvp.js:1043
18747 83.8% 0 0.0% LazyCompile: lib$rsvp$$internal$$tryCatch /src/node_modules/rsvp/dist/rsvp.js:1034
18746 83.8% 0 0.0% LazyCompile: ~<anonymous> /src/lib/promised-queue.js:29
18736 83.8% 0 0.0% LazyCompile: ~logError /src/lib/promised-queue.js:80
18736 83.8% 0 0.0% LazyCompile: ~target.(anonymous function) /src/node_modules/winston/lib/winston/common.js:41
18736 83.8% 0 0.0% LazyCompile: ~Logger.log /src/node_modules/winston/lib/winston/logger.js:123
18736 83.8% 0 0.0% LazyCompile: ~async.each /src/node_modules/winston/node_modules/async/lib/async.js:104
18736 83.8% 0 0.0% LazyCompile: ~_each /src/node_modules/winston/node_modules/async/lib/async.js:30
18736 83.8% 0 0.0% LazyCompile: *forEach native array.js:1087
18736 83.8% 0 0.0% LazyCompile: ~<anonymous> /src/node_modules/winston/node_modules/async/lib/async.js:110
18736 83.8% 0 0.0% LazyCompile: ~emit /src/node_modules/winston/lib/winston/logger.js:175
18736 83.8% 0 0.0% LazyCompile: ~Console.log /src/node_modules/winston/lib/winston/transports/console.js:56
18736 83.8% 0 0.0% LazyCompile: ~exports.log /src/node_modules/winston/lib/winston/common.js:112
18736 83.8% 0 0.0% LazyCompile: ~decycle /src/node_modules/cycle/cycle.js:24
18736 83.8% 0 0.0% Function: ~derez /src/node_modules/cycle/cycle.js:46
18736 83.8% 0 0.0% Function: ~derez /src/node_modules/cycle/cycle.js:46
18736 83.8% 0 0.0% Function: ~derez /src/node_modules/cycle/cycle.js:46
18736 83.8% 0 0.0% Function: ~derez /src/node_modules/cycle/cycle.js:46
18736 83.8% 0 0.0% Function: ~derez /src/node_modules/cycle/cycle.js:46
18736 83.8% 0 0.0% Function: ~derez /src/node_modules/cycle/cycle.js:46
18736 83.8% 0 0.0% Function: ~derez /src/node_modules/cycle/cycle.js:46
18551 82.9% 998 4.5% Function: ~derez /src/node_modules/cycle/cycle.js:46
4754 21.3% 4754 21.3% /opt/node-v0.10.31-linux-x64/bin/node
3805 17.0% 296 1.3% Function: ~derez /src/node_modules/cycle/cycle.js:46
Looking above the winston tick the last part of my code before calling the winston lib is:
LazyCompile: ~logError /src/lib/promised-queue.js:80
And that is the end. Looking into my code /src/lib/promised-queue.js at line 80. The function logError really was calling the winston library. Based on this knowledge my approach was simplest replacing winston with console.log because at that part a simple print of the error into the console was enough.
16 May 2016
Lately I was getting a lot of problems with my VM and even with the bluetooth on Mac.
Just because the vmware VM was not recovering well after my macbook waking up.
I use a VM everyday and I always forget to suspend/halt that before sleep my macbook.
So I find out is possible to configure scripts to be executed on wakeup/sleep the machine through SleepWatcher.
This blog post Mac OS X: Automating Tasks on Sleep by Kodiak explain really well how to setup the sleepwatcher.
Summarizing:
# 1. install
brew install sleepwatcher
# 2. create a script "~/.sleep" to be executed before the machine sleep
# in my case was "cd <vm-directory> && vagrant suspend"
# 3. set full permissions to the owner
chmod 700 ~/.sleep
# 4. start the watcher then put your machine to sleep to test the script is working
/usr/local/sbin/sleepwatcher --verbose --sleep ~/.sleep
# configure the deamon
sudo chown root:wheel /usr/local/Cellar/sleepwatcher/2.2/de.bernhard-baehr.sleepwatcher-20compatibility-localuser.plist
ln -sfv /usr/local/Cellar/sleepwatcher/2.2/de.bernhard-baehr.sleepwatcher-20compatibility-localuser.plist ~/Library/LaunchAgents/
launchctl load ~/Library/LaunchAgents/de.bernhard-baehr.sleepwatcher-20compatibility-localuser.plist
28 Jan 2016
At Bravi every project has multi tenant support since the beginning of the development.
This because we have built a solution that is so easy to use that is almost imperceptible we are developing a multi tenant application. The only thing we have to care about is:
- pass ahead in the HTTP header the tenant id for every consumed API/application
- use a prefix in the table on executing SQL queries
select * from "$_mytable"
And that is it. You are already building a multi tenant application.
How does that work?
Well. The library knextancy takes care of everything for us.
Knextancy is built on top of knex and implements multi tenant using table prefixes. So all the clients share the same database but each one has it own table. For example:
Every time a request like this one below is done:
curl -X GET -H "x-client-id: 11" "http://localhost:3000/"
Knextancy will identify the tenant associated to that request based in the x-client-id. In case is the first request for that server, knextancy also will execute the migration and seed tasks. So there is no manual configuration required for bringing up a database for a new client.
You may ask yourself. How is that secure if the tenant is based in HTTP header? Then the user could change manually the tenant he is accessing.
Well. This is not a problem for services running inside a private network. For the public app/services, we run everything behind a proxy, that injects the x-client-id based in the domain.
After that knextancy injects in the request an instance of knex with the context of the current client (e.g. req.knex).
Then to execute any SQL query with multi tenant support is just required to use the req.knex and any table must have prefix $_ to allow knextancy resolve the table for the current client.
Simple example of how to build a multi tenant REST API. Using knextancy with express and PostgreSQL database.
https://github.com/bravi-software/knextancy-example
20 Dec 2015
It is a post for beginners in Elixir and Phoenix. Has intention to help understanding how a Phoenix application works and a bit of its lifecycle.
I started the day thinking in write an chat application to apply what I have learned so far of Elixir. But even after reading the whole Elixir - Getting Started and Phoenix - Up And Running. I was not really feeling prepared to write an application on my own.
P.S. I didn’t read the Phoenix framework documentation before start the application. I’m sure if I had read the docs, everything would makes sense. But I was just too excited to start coding :D.
So instead of writing a chat app from scratch. What we gonna do is understand how the chat app built by Chris McCord works.
Before understanding, lets see the application running:
- Clone the repo chrismccord/phoenix_chat_example, then cd to the new directory
- Install dependencies with
mix deps.get
- (optional) Install npm dependencies to customize the ES6 js/Sass
npm install
- Start Phoenix router with
mix phoenix.server
Now you can visit localhost:4000 from your browser.
mix.exs
Contains the definition for all dependencies and configures the OTP application.
Check out elixir/Application to understand what is an OTP application. And the presentation OTP Has Done It - by Nick DeMonner also gives an idea about it.
defmodule Chat.Mixfile do
use Mix.Project
def project do
[app: :chat,
version: "0.0.1",
elixir: "~> 1.0",
elixirc_paths: ["lib", "web"],
compilers: [:phoenix] ++ Mix.compilers,
deps: deps]
end
# Configuration for the OTP application
#
# Type `mix help compile.app` for more information
def application do
[mod: {Chat, []},
applications: [:phoenix, :phoenix_html, :cowboy, :logger]]
end
# Specifies your project dependencies
#
# Type `mix help deps` for examples and options
defp deps do
[{:phoenix, "~> 1.0.0"},
{:phoenix_html, "~> 2.1"},
{:phoenix_live_reload, "~> 1.0", only: :dev},
{:phoenix_ecto, "~> 1.1"},
{:postgrex, ">= 0.0.0"},
{:cowboy, "~> 1.0"}]
end
end
In the application function is defined the Chat as the startup module. And also is defined all applications your application depends on at runtime.
lib/chat.ex
defmodule Chat do
use Application
# See http://elixir-lang.org/docs/stable/elixir/Application.html
# for more information on OTP Applications
def start(_type, _args) do
import Supervisor.Spec, warn: false
children = [
# Start the endpoint when the application starts
supervisor(Chat.Endpoint, []),
# Start the Ecto repository
worker(Chat.Repo, []),
# Here you could define other workers and supervisors as children
# worker(Chat.Worker, [arg1, arg2, arg3]),
]
# See http://elixir-lang.org/docs/stable/elixir/Supervisor.html
# for other strategies and supported options
opts = [strategy: :one_for_one, name: Chat.Supervisor]
Supervisor.start_link(children, opts)
end
# Tell Phoenix to update the endpoint configuration
# whenever the application is updated.
def config_change(changed, _new, removed) do
Chat.Endpoint.config_change(changed, removed)
:ok
end
end
In lib/chat.ex is defined the OTP Application. As we can see the Chat.Endpoint is started as supervisor. Which will start the endpoint when the application starts and it will be restarted in case it crashes.
And Chat.Repo is started as worker. Which will run the repository in a different process. Allowing this way to keep the state (e.g. connection pool) between different requests. Otherwise would be necessary establish a new DB connection for every request.
lib/chat/endpoint.ex
defmodule Chat.Endpoint do
use Phoenix.Endpoint, otp_app: :chat
# Requests coming at "/socket" path will be handled by
# UserSocket (web/channels/user_socket.ex)
socket "/socket", Chat.UserSocket
# Serve at "/" the given assets from "priv/static" directory
plug Plug.Static,
at: "/", from: :chat,
only: ~w(css images js favicon.ico robots.txt)
# Code reloading will only work if the :code_reloader key of
# the :phoenix application is set to true in your config file.
if code_reloading? do
socket "/phoenix/live_reload/socket", Phoenix.LiveReloader.Socket
plug Phoenix.CodeReloader
plug Phoenix.LiveReloader
end
# Log the requests
plug Plug.Logger
# Configure parsers
plug Plug.Parsers,
parsers: [:urlencoded, :multipart, :json],
pass: ["*/*"],
json_decoder: Poison
plug Plug.MethodOverride
plug Plug.Head
plug Plug.Session,
store: :cookie,
key: "_chat_key",
signing_salt: "LH6XmqGb",
encryption_salt: "CIPZg4Qo"
# Only after passing through all the previous Plug
# the request will be handled by the Chat.Router (web/router.ex)
plug Chat.Router
end
In lib/chat/endpoint.ex is used a lot Plug. It allows compose modules between web applications. With Plug is possible to change the request and response data through the connection lifecycle. It is comparable to a middleware in Node JS.
Check out understanding-plug and plug project.
web/router.ex
defmodule Chat.Router do
use Phoenix.Router
pipeline :browser do
plug :accepts, ["html"]
plug :fetch_session
plug :fetch_flash
plug :protect_from_forgery
end
pipeline :api do
plug :accepts, ["json"]
end
scope "/", Chat do
pipe_through :browser # Use the default browser stack
get "/", PageController, :index
end
end
In Chat.Router we see the definition of pipeline. Which is a simple way to pipe a series of plug before passing the request ahead to a controller. That can be used for different type of requests. For example: an API request must be handled differently of a browser (page) request.
Once a request arrives at the Phoenix router, it performs a series of transformations through pipelines until the request is dispatched to a desired end-point.
Such transformations are defined via plugs, as defined in the Plug specification. Once a pipeline is defined, it can be piped through per scope.
http://hexdocs.pm/phoenix/Phoenix.Router.html
web/controllers/page_catroller.ex
defmodule Chat.PageController do
use Chat.Web, :controller
def index(conn, _params) do
render conn, "index.html"
end
end
After a request passing through all previous plug. It will be handled by the controller. For instance a GET / will respond with index.html page.
channels/user_socket.ex
As we saw before in the Chat.Endpoint the socket connections will be handled by the Chat.UserSocket.
defmodule Chat.UserSocket do
use Phoenix.Socket
channel "rooms:*", Chat.RoomChannel
transport :websocket, Phoenix.Transports.WebSocket
transport :longpoll, Phoenix.Transports.LongPoll
def connect(_params, socket) do
{:ok, socket}
end
def id(_socket), do: nil
end
Basically the Chat.UserSocket creates a channel for topics matching rooms:*. And add support for both web socket and log pool connections.
channels/room_socket.ex
defmodule Chat.RoomChannel do
use Phoenix.Channel
require Logger
@doc """
Authorize socket to subscribe and broadcast events on this channel & topic
Possible Return Values
`{:ok, socket}` to authorize subscription for channel for requested topic
`:ignore` to deny subscription/broadcast on this channel
for the requested topic
"""
def join("rooms:lobby", message, socket) do
# Exit signals arriving to a process are converted to {'EXIT', From, Reason} messages,
# which can be received as ordinary messages
Process.flag(:trap_exit, true)
:timer.send_interval(5000, :ping)
send(self, {:after_join, message})
{:ok, socket}
end
def join("rooms:" <> _private_subtopic, _message, _socket) do
{:error, %{reason: "unauthorized"}}
end
def handle_info({:after_join, msg}, socket) do
broadcast! socket, "user:entered", %{user: msg["user"]}
push socket, "join", %{status: "connected"}
{:noreply, socket}
end
def handle_info(:ping, socket) do
push socket, "new:msg", %{user: "SYSTEM", body: "ping"}
{:noreply, socket}
end
def terminate(reason, _socket) do
Logger.debug"> leave #{inspect reason}"
:ok
end
def handle_in("new:msg", msg, socket) do
broadcast! socket, "new:msg", %{user: msg["user"], body: msg["body"]}
{:reply, {:ok, %{msg: msg["body"]}}, assign(socket, :user, msg["user"])}
end
end
Pretty simple, it handles:
- new users join the channel
- broadcast new users in the chat
- send ping messages
- broadcast a user’s message
Check out Phoenix.Channel for a further explanation.
The rest is just a HTML page loading a CSS script (source in Sass) and a Javascript script (source in ES6) which consumes the socket provided by the Chat channel.
P.S. I have just started learning Elixir and Phoenix. Let me know if I had misunderstood something.
