ACM Transactions on Software Engineering and Methodology, Vol. 29, No. 2, Article 9. Pub. date: March 2020.

Visualizing Distributed System Executions

In addition to the acquisition time disparity, the researcher used ShiViz to determine that (1) one thread does different work than the others (based on the amount of time spent in this thread). By examining the code, the researcher realized that this thread is a work producer. (2) Using ShiViz, the researcher realized that the pthread mutex is unfair relative to the ticket-based lock—some threads acquire the lock more often than others when using the pthread mutex, which creates a priority inversion. And, (3) the priority inversion makes the work producer thread run more often when using the pthread mutex than when using the ticket lock. Since the work producer is the bottleneck in the studied workload, the workload ends up completing faster with the pthread

In summary, the researcher noted that ShiViz helped her solve the problem faster than if she used other tools: “I seriously doubt that I would have been able to pinpoint the precise cause of the problem without ShiViz, and even if I had, it would have taken me many weeks.”

Vector Clock Instrumentation Overhead

Our XVector vector clock instrumentation libraries have (1) a network overhead due to the ad- ditional vector clock timestamps in network payloads, and (2) a vector clock logging overhead. We evaluate both of these overheads in the GoVector library, which is an XVector library for Go lang. Our experience using other XVector libraries in teaching and with open-source systems in- dicates that the other XVector libraries have similar overheads. We use GoVector to instrument etcd,7 a popular distributed key value store that uses the Raft consensus protocol [87] to achieve

Experimental setup. We ran all experiments on an Intel machine with a 4-core i5 CPU and 8 GB of memory. The machine was running Ubuntu 14.04 and all applications were compiled using Go 1.6 for Linux/amd64. We exercised etcd by loading it using the Yahoo! Cloud Serving Benchmark (YCSB-B)8 with a uniform distribution (50% gets and 50% puts on random keys). The etcd Raft cluster consisted of three replication nodes. We measured the latency and goodput9 on both the uninstrumented and the instrumented versions of etcd. In both experiments, the maximum number of clients that could execute concurrently without reaching maximum CPU utilization was 72.

identity and the other is the node’s logical clock timestamp. The overhead of vector clocks is fore a product of the number of nodes interacting during execution and the number of · · 64 bits nodes messages. In practice, adding vector clocks to messages slows down each which can impact the behavior of the system.

Figure 11 shows the goodput for uninstrumented and instrumented Raft with each point repre- senting an average over three executions. Adding vector clocks to Raft slowed down the broadcast of heartbeat messages and caused an increase in goodput with 36 clients. As the number of clients grew, the size of the vector clocks overcame this goodput saving. Across these experiments, good- put decreased by 13% on average and the maximum decrease was 23%.

Latency overhead. GoVector imposes a latency overhead in computing vector clocks and in se- rializing and deserializing messages with vector clocks. Figure 12 shows Raft’s latency processing client requests in the uninstrumented and instrumented versions of Raft. Across these experiments, the latency increase was 7% on average with a maximum increase of 21%.

9Goodput is application-level throughput. For etcd, it is the number of client requests that the system can process per unit time.

ACM Transactions on Software Engineering and Methodology, Vol. 29, No. 2, Article 9. Pub. date: March 2020.



Fig. 11. Goodput of uninstrumented and instrumented etcd Raft.



12. Latency of uninstrumented and instrumented etcd Raft.

Logging overhead. In the above experiment, we also collected information on logging over- head. We found that the average execution time of a single logging statement is 20 microseconds. In our local area network with a round trip time of 0.05 milliseconds while running etcd with 1-second timeouts, we were able to execute approximately 50K logging statements per node be- fore perturbing the system.

The overhead imposed by XVector makes it a viable tool during development, but not in produc- tion. We believe that existing distributed tracing systems, such as X-Trace [39] and Dapper [110], which are intended for production use, can be extended with tracking of vector-clock timestamps. We have also successfully reconstructed ShiViz-compatible logs from X-Trace traces.10

ShiViz Scalability on Synthetic and Benchmark Logs

ShiViz is designed to run in the browser, making it more accessible and easier to use. However, design choice does impact its ability to scale to large and complex logs. In this section, we scalability results from using ShiViz on a variety of logs. In each experiment, we report the to load and visualize the log with ShiViz in a browser. In every log we experimented with, remained real-time interactive after the visualization was rendered.

We ran all experiments on a Mac Air laptop running OS X 10.13.6 with a 2.2 GHz i7 processor and 8 GB RAM. We used a 64-bit version of the Chrome browser version 76.0.3809 with the latest version of ShiViz (commit id 4d89184c2d12). In the first three experiments, we generated synthetic logs that had specific characteristics to allow us to control for different scalability factors. In the fourth experiment, we used logs collected from a microservices-based social network system with 36 unique microservices [42].

In the first experiment, we varied the number of events in the log. Each log in this had 12 hosts; every other event in each log was a communication event (that is, 50% of the

10https://github.com/MPI-SWS/xtrace-shiviz/.