Trace-Based Run-Time Analysis of Message-Passing Go Programs

In Listing 1 we find a Go program implementing a system of newsreaders. The main function creates two synchronous channels, one for each news agency. Go supports (a limited form of) type inference and therefore no type annotations are required. Next, we create one thread per news agency via the keyword go. Each news agency transmits news over its own channel. In Go, we write ch <- "REUTERS" to send value "REUTERS" via channel ch. We write <-ch to receive a value via channel ch. As we assume synchronous channels, both operations block and only unblock once a sender finds a matching receiver. We find two newsreader instances. Each newsreader creates two helper threads that wait for news to arrive and transfer any news that has arrived to a common channel. The intention is that the newsreader wishes to receive any news whether it be from Reuters or Bloomberg. However, there is a subtle bug (to be explained shortly).

We only consider finite program runs and therefore each of the news agencies supplies only a finite number of news (exactly one in our case) and then terminates. During program execution, we trace communication events, e.g. send and receive, that took place. Due to concurrency, a bug may not manifest itself because a certain ‘bad’ schedule is rarely taken in practice.

Here is a possible trace resulting from a ‘good’ program run.

r!; N1.r?; N1.ch!; N1.ch?; b!; N2.b?; N2.ch!; N2.ch?

We write r! to denote that a send event via the Reuters channel took place. As there are two instances of the newsReader function, we write N1.r? to denote that a receive event via the local channel took place in case of the first newsReader call. From the trace we can conclude that the Reuters news was consumed by the first newsreader and the Bloomberg news by the second newsreader.

Here is a trace resulting from a bad program run.

r!; b!; N1.r?; N1.b?; N1.ch!; N1.ch?; DEADLOCK

The helper thread of the first newsreader receives the Reuters and the Bloomberg news. However, only one of these messages will actually be read (consumed). This is the bug! Hence, the second newsreader gets stuck and we encounter a deadlock. The issue is that such a bad program run may rarely show up. So, the question is how can we assist the user based on the trace information resulting from a good program run? How can we infer that alternative schedules and communications may exist?

A well-established approach is to derive a partial order among events. This is usually achieved via a vector of (logical) clocks. The vector clock method was independently developed by Fidge [1] and Mattern [8]. For the above good program run, we obtain the following partial order among events.

r! < N1.r?         b! < N2.b?
N1.r? < N1.ch!     N2.b? < N2.ch!  (1)
N1.ch! < N1.ch?    N2.ch! < N2.ch? (2)

For example, (1) arises because N2.ch! happens (sequentially) after N2.b? For synchronous send/receive, we assume that receive happens after send. See (2). Based on the partial order, we can conclude that alternative schedules are possible. For example, b! could take place before r!. However, it is not clear how to infer alternative communications. Recall that the issue is that one of the newsreaders may consume both news messages. Our proposed method is able to clearly identify this issue and has the advantage to require a much simpler instrumentation We discuss these points shortly. First, we take a closer look at the details of instrumentation for the vector clock method.

Vector clocks are a refinement of Lamport’s time stamps [7]. Each thread maintains a vector of (logical) clocks of all participating partner threads. For each communication step, we advance and synchronize clocks. In pseudo code, the vector clock instrumentation for event sndR.

We assume that vc holds the vector clock. The clock of the Reuters thread is incremented. Besides the original value, we transmit the sender’s vector clock and a helper channel vcCh. For convenience, we use tuple notation. The sender’s vector clock is updated by building the maximum among all entries of its own vector clock and the vector clock of the receiving party. The same vector clock update is carried out on the receiver side.

We propose a much simpler instrumentation and tracing method to obtain a partial order among events. Instead of a vector clock, each thread traces the events that might happen and have happened. We refer to them as pre and post events. In pseudo code, our instrumentation for sndR looks like follows.

The bang symbol (‘!’) indicates a send operation. Function hash builds a hash index of channel names. The sender transmits its thread id number to the receiver. This is the only intra-thread overhead. No extra communication link is necessary.

Here are the traces for individual threads resulting from the above good program run.

R:           pre(r!); post(r!)
N1_helper1:  pre(r?); post(R#r?); pre(ch1!); post(ch1!)
N1_helper2:  pre(b?)
N1:          pre(ch1?); post(N1_helper1#ch1?)
B:           pre(b!); post(b!)
N2_helper1:  pre(r?)
N2_helper2:  pre(b?); post(B#b?); pre(ch2!); post(ch2!)
N2:          pre(ch2?); post(N2_helper2#ch2?)

We write pre(r!) to indicate that a send via the Reuters channel might happen. We write post(R#r?) to indicate that a receive has happened via thread R. The partial order among events is obtained by a simple post-processing phase where we linearly scan through traces. For example, within a trace there is a strict order and therefore

N2_helper2:  pre(b?); post(B#b?); pre(ch2!); post(ch2!)

implies N2.b? < N2.ch!. Across threads we check for matching pre/post events. Hence,

R:           pre(r!); post(r!)
N1_helper1:  pre(r?); post(R#r?); ...

implies r! < N1.r?. So, we obtain the same (partial order) information as the vector clock approach but with less overhead.

The reduction in terms of tracing overhead compared to the vector clock method is rather drastic assuming a library-based tracing scheme with no access to the Go run-time system. For each communication event we must exchange vector clocks, i.e. $n$ additional (time stamp) values need to be transmitted where $n$ is the number of threads. Besides extra data to be transmitted, we also require an extra communication link because the sender requires the receivers vector clock. In contrast, our method incurs a constant tracing overhead. Each sender transmits in addition its thread id. No extra communication link is necessary. This results in much less run-time overhead as we will see later.

The vector clock tracing method can be improved assuming we extend the Go run-time system. For example, by maintaining a per-thread vector clock and having the run-time system carrying out the exchange of vector clocks for each send/receive communication. There is still the $O(n)$ space overhead. Our method does not require any extension of the Go run-time system to be efficient and therefore is also applicable to other languages that offer similar features as found in Go.

A further advantage of our method is that we also trace (via pre) events that could not commit (post is missing). Thus, we can easily infer alternative communications. For example, for R: pre(r!); ... there is the alternative match N2_helper1: pre(r?). Hence, instead of r! < N1.r? also r! < N2.r? is possible. This indicates that one newsreader may consume both news message. The vector clock method, only traces events that could commit, post events in our notation. Hence, the above alternative communication could not be derived.

Compared to earlier works based on the vector clock method, we propose a much more light-weight and more informative instrumentation and tracing scheme. Specifically, we make the following contributions:

• •

  We give a precise account of our run-time tracing method (Section 3) for message-passing as found in the Go programming language (Section 2) where for space reasons we only formalize the case of synchronous channels and selective communications.

• •

  A simple analysis of the resulting traces allows us to detect alternative schedules and communications (Section 4). For efficiency reasons, we employ a directed dependency graph to represent happens-before relations (Section 4.1).

• •

  We show that vector clocks can be easily recovered based on our tracing method (Section 5). We also discuss the pros and cons of both methods for analysis purposes.

• •

  Our tracing method can be implemented efficiently as a library. We have fully implemented the approach supporting all Go language features dealing with message-passing such as buffered channels, select with default or timeout and closing of channels (Section 6).

• •

  We provide experimental results measuring the often significantly lower overhead of our method compared to the vector clock method assuming based methods are implemented as libraries (Section 6.2).

The online version of this paper contains an appendix with further details.¹¹1https://arxiv.org/abs/1709.01588

For brevity, we consider a much simplified fragment of the Go programming language. We only cover straight-line code, i.e. omitting procedures, if-then-else etc. This is not an onerous restriction as we only consider finite program runs. Hence, any (finite) program run can be represented as a program consisting of straight-line code only.

For our purposes, values are integers or lists (slices in Go terminology). For lists we follow Haskell style notation and write $b:bs$ to refer to a list with head element $b$ and tail $bs$. We can access the head and last element in a list via primitives ${\sf head}$ and ${\sf last}$. We often write $[b_{1},\dots,b_{n}]$ as a shorthand $b_{1}:\dots:[]$. Primitive tid yields the thread id number of the current thread. We assume that the main thread always has thread id number $1$ and new thread id numbers are generated in increasing order. Primitive ${\sf hash}()$ yields a unique hash index for each variable name. Both primitives show up in our instrumentation.

A program is a sequence of commands where commands are stored in a list. Primitive makeChan creates a new synchronous channel. Primitive go creates a new go routine (thread). For send and receive over a channel we follow Go notation. We assume that a receive is always tied to an assignment. For assignment we use symbol $:=$ to avoid confusion with the mathematical equality symbol $=$. In Go, symbol $:=$ declares a new variable with some initial value. We also use $:=$ to overwrite the value of existing variables. As a message passing command we only support selective communication via select. Thus, we can fix the bug in our newsreader example.

The select statement guarantees that at most one news message will be consumed and blocks if no news are available. In our simplified language, we assume that the $x\leftarrow b$ command is a shorthand for $\mbox{\sf select}\ [x\leftarrow b\Rightarrow[]]$. For space reasons, we omit buffered channels, select paired with a default/timeout case and closing of channels. All three features are fully supported by our implementation.

The semantics of programs is defined via a small-step operational semantics. The semantics keeps track of the trace of channel-based communications that took place. This allows us to relate the traces obtained by our instrumentation with the actual run-time traces.

We support multi-threading via a reduction relation

We write $i\sharp p$ to denote a program $p$ that runs in its own thread with thread id $i$. We use lists to store the set of program threads. The state of program variables, before and after execution, is recorded in $S$ and $S^{\prime}$. We assume that threads share the same state. Program trace $T$ records the sequence of communications that took place during execution. We write $x!$ to denote a send operation on channel $x$ and $x?$ to denote a receiver operation on channel $x$. The semantics of expressions is defined in terms a big-step semantics. We employ a reduction relation $(i,S)\,\vdash\,b\Downarrow v$ where $S$ is the current state, $b$ the expression and $v$ the result of evaluating $b$. The formal details follow.

A state $S$ is either empty, a mapping, or an override of two states. Each state maps variables to storables. A storable is either a plain value or a channel. Variable names may appear as values. In an actual implementation, we would identify the variable name by a unique hash index. We assume that mappings in the right operand of the map override operator $\lhd$ take precedence. They overwrite any mappings in the left operand. That is, $(x\mapsto v_{1})\lhd(x\mapsto v_{2})=(x\mapsto v_{2})$.

We write $(S,P)\ext@arrow 0359\Rightarrowfill@{}{}(S^{\prime},Q)$ as a shorthand for $(S,P)\ext@arrow 0359\Rightarrowfill@{}{[]}(S^{\prime},Q)$.