Wednesday, 20 September 2017

Ubuntu upstart service for my golang web application

I have one web application written in go and need to deploy it as a service in Ubuntu server, say the name of the app is hello.
Copy the app to some directory in the server (e.g. /app directory, so the application binary is /app/hello)
Create an upstart script (e.g. hello.conf) and place it in /etc/init.
We run the binary using the following line:

exec start-stop-daemon --start \
--pidfile /var/run/ \
--make-pidfile \

To send the stdout and stderr of the application to a log file (e.g. /logs/app/hello/hello.log), we can edit the start-stop-daemon command line:

exec start-stop-daemon --start \
--pidfile /var/run/ \
--make-pidfile \
--startas /bin/bash -- -c "exec $DAEMON $DAEMON_OPTS >> /logs/app/hello/hello.log 2>&1"

Now say we want to collect the summary of garbage collection and go scheduler trace in the log file. We have to change the Go’s runtime environment variable GODEBUG.
GODEBUG=gctrace=1 enables garbage collector (GC) trace. The garbage collector emits a single line to STDERR at each collection. The collector summarizes the amount of memory collected and the length of the garbage collection pause.
To investigate the operation of the runtime scheduler directly, and to get insights into dynamic behaviour of the goroutine scheduler, we can enable the scheduler trace. To enable the scheduler trace we can set:
The value 1000 is in milliseconds. So the above setting will make the scheduler to emit a single line to standard error every second.
We can combine both garbage collection and scheduler trace as GODEBUG=gctrace=1,schedtrace=30000

So again editing the start-stop-daemon command line:

exec start-stop-daemon --start \
--pidfile /var/run/ \
--make-pidfile \
--startas /bin/bash -- -c "exec /usr/bin/env GODEBUG=gctrace=1,schedtrace=30000 $DAEMON $DAEMON_OPTS >> /logs/app/hello/hello.log 2>&1"

A garbage collection log line looks like:
gc 56 @27.196s 0%: 0.010+3.7+0.014 ms clock, 0.010+0.80/2.6/0+0.014 ms cpu, 4->4->0 MB, 5 MB goal, 1 P
gc 57 @27.260s 0%: 0.007+2.1+0.010 ms clock, 0.007+0.35/1.0/0+0.010 ms cpu, 4->4->0 MB, 5 MB goal, 1 P

56: the GC number, incremented at each GC
@27.196s: time in seconds since program start
0%: percentage of time spent in GC since program start
0.010+3.7+0.014 ms clock: wall-clock times for the phases of the GC
0.007+0.35/1.0/0+0.010 ms cpu: CPU times for the phases of the GC
4->4->0 MB: heap size at GC start (4MB), at GC end (4MB), and live heap (0MB)
5 MB goal: goal heap size
1 P: number of processors used, here 1 processor used

A scheduler trace line looks like:
SCHED 25137ms: gomaxprocs=1 idleprocs=0 threads=4 spinningthreads=0 idlethreads=1 runqueue=2 [98]

25137ms : Time since program start
gomaxprocs=1: Gomaxprocs is the current value of GOMAXPROCS. The GOMAXPROCS variable limits the number of operating system threads that can execute user-level Go code simultaneously. Starting with Go 1.5, GOMAXPROCS is set to number of CPUs available by default.
idleprocs=0: Number of processors that are not busy. So here 0 processors are idle.
threads=4: Number of threads that the runtime is managing.
spinningthreads=0: Number of spinning threads.
idlethreads=1: Number of threads that are not busy. 1 thread is idle and (3 are running).
runqueue=2: Runqueue is the length of global queue with runnable goroutines.
[98]: Number of goroutines in the local run queue. For a machine with multiple processors we can see multiple values for each processor e.g. [2 2 2 3].
The init script is available here