Falcon: A Practical Log-Based Analysis Tool for Distributed Systems

Presented at Dependable Systems and Networks (DSN) 2018.

Falcon is a tool aimed at making log-based analysis of distributed systems practical and effective. Falcon’s modular architecture, designed as an extensible pipeline, allows it to seamlessly combine several distinct logging sources and generate a coherent space-time diagram of distributed executions. To preserve event causality, even in the presence of logs collected from independent unsynchronized machines, Falcon introduces a novel happens-before symbolic formulation and relies on an off- the-shelf constraint solver to obtain a coherent event schedule.

Transcript

1. Falcon: A Practical Log-Based Analysis Tool for Distributed Systems Francisco Neves, Nuno Machado and José Pereira HASLab, INESC TEC and University of Minho Braga, Portugal 28 June, 2018 Luxembourg City, Luxembourg IEEE/IFIP International Conference on Dependable Systems and Networks
2. Introduction • Developers still debug runtime executions using log data • Log-based analysis is a daunting task in distributed systems ◦ Sheer number of log entries ◦ Multiple and heterogeneous log files scattered across several nodes ◦ Physical clock skew and log messages produced asynchronously 2
3. Case Study - ZooKeeper Leader Election (in Theory) 3
4. Case Study - ZooKeeper Leader Election (in Practice) 4
5. 5 2018-06-12 19:25:33,939 [myid:3] - DEBUG [QuorumPeer[myid=3]/0.0.0.0:2181:FastLeaderElection@672] - Sending Notification: 3 (n.leader), 0x0 (n.zxid), 0x1 (n.round), 2 (recipient), 3 (myid), 0x0 (n.peerEpoch) Case Study - ZooKeeper Leader Election (in Practice) 2018-06-12 19:25:33,938 [myid:2] - DEBUG [QuorumPeer[myid=2]/0:0:0:0:0:0:0:0:2181:FastLeaderElectio n@789] - Updating proposal: 3 (newleader), 0x0 (newzxid), 2 (oldleader), 0x0 (oldzxid)
6. 6 Case Study - ZooKeeper Leader Election (in Practice)
7. Causality Lamport defines a relationship called happens-before “a → b” is read as “a happens before b” 1. if a and b are events in the same process and a occurs before b, then a → b 2. if a is the event of a message being sent by one process and b is the event of the message being received by another process, then a → b 3. “happens-before” is transitive, meaning if a → b and b → c, then a → c 7
8. Tracing tools for debugging 8 Commodity tracing tools • strace • ltrace • ptrace • perf • eBPF • DTrace • LTTng State-Of-The-Art tracing tools • Pinpoint [DSN’02] • X-Trace [NSDI’07] • Google Dapper • Twitter Zipkin • OpenTracing • Pivot Tracing [SOSP’15] • Canopy [SOSP’17]  Source/protocol-dependent  Manual instrumentation  Causality  Source/protocol-agnostic  Out-of-the-box instrumentation  Lack of Causality
9. Falcon: A practical log-based analysis tool 9  Source/protocol-agnostic  Out-of-the-box instrumentation  Causality • Combines events from distinct tracing tools into a causally coherent space-time diagram of the distributed execution.
10. 3. Generate the space-time diagram Falcon — Overview 10 1. Parse the output of different tracing tools 2. Compute logical time according to causality
11. 3. Generate the space-time diagram Falcon — Overview 11 1. Parse the output of different tracing tools 2. Compute logical time according to causality
12. 1. Parse the output of different tracing tools • Current drivers support: strace, log4j 12 ◦ CONNECT (process, src, dst) ◦ ACCEPT (process, src, dst) ◦ SND (process, src, dst, msg) ◦ RCV (process, src, dst, msg) ◦ START (process) ◦ END (process) ◦ FORK (parent, child) ◦ JOIN (parent, child) ◦ LOG (process, msg) Low-level Events User-level Events • Falcon uses drivers for translating the output of tracing tools into events with a common format:
13. 1. Parse the output of different tracing tools • Example: for strace, the driver translates system calls into Falcon events: 13 System Call Falcon event(s) fork() FORK + START wait() JOIN + END exit() END connect() CONNECT accept() ACCEPT write() / sendmsg() / sendto() / ... SND read() / recvmsg() / ... RCV
14. 3. Generate the space-time diagram Falcon — Overview 14 2. Compute logical time according to causality 1. Parse the output of different tracing tools
15. 2. Compute logical time according to causality • Cast logical time assignment as a constraint solving problem ◦ Each event’s logical timestamp is represented as a symbolic integer variable ◦ Symbolic variable values must satisfy intra-process and inter-process causality constraints • Solving the model with an off-the-shelf solver (e.g. Z3) outputs a trace of logically-timestamped events that satisfy causality 15
16. • Happens-before model to obtain event logical timestamps: 2. Compute logical time according to causality 16 Φ HB = φ inter  φ intra  GOAL
17. • Happens-before model to obtain event logical timestamps: 2. Compute logical time according to causality 17 Φ HB = φ inter  φ intra  GOAL Inter-process causality constraints ◦ SNDp,m < RCVq,m ◦ CONNECTp < ACCEPTq ◦ FORKp,q < STARTq ◦ ENDq < JOINp,q
18. • Happens-before model to obtain event logical timestamps: 2. Compute logical time according to causality 18 Φ HB = φ inter  φ intra  GOAL Intra-process causality constraints ◦ Γ p is the event trace of process p ◦ ci and cj are symbolic variables for logical timestamps of events i and j ◦  i, j  Γ p : (i < j
    ci < cj )
19. • Happens-before model to obtain event logical timestamps: 2. Compute logical time according to causality 19 Φ HB = φ inter  φ intra  GOAL Soft constraint that allows steering the constraint solving procedure:  to follow the original timestamp order  to minimize the logical clock values (i.e. to expose concurrency)
20. 3. Generate the space-time diagram Falcon — Overview 20 2. Compute logical time according to causality 1. Parse the output of different tracing tools
21. 3. Generate the space-time diagram 21
22. 3. Generate the space-time diagram 22 Logical Timestamps
23. 3. Generate the space-time diagram 23 Thread Timeline
24. 3. Generate the space-time diagram 24 Thread Identifier
25. 3. Generate the space-time diagram 25 Thread Event
26. 3. Generate the space-time diagram 26 Threads under the same Process
27. 3. Generate the space-time diagram 27 Happens-Before relationship between two events of distinct threads/processes
28. Case Study — Apache Zookeeper • Experimental setting: ◦ Two Zookeeper instances executing the Leader Election algorithm ◦ Tracing tools: ptrace-based tool and log4j  Our ptrace-tool is quite similar to strace but outputs Falcon events  The log4j configuration includes a new appender that formats log messages according to Falcon’s event specification • Research Questions: ◦ Space-time diagram usefulness ◦ Tracing overhead ◦ Constraint solving performance 28
29. Case Study — Space-Time Diagram Usefulness (1/3) 29
30. Case Study — Space-Time Diagram Usefulness (1/3) 30 Zookeeper uses DataOutputStream class. The writeInt method of this class calls the write syscall per byte
31. Case Study — Space-Time Diagram Usefulness (2/3) 31
32. Case Study — Space-Time Diagram Usefulness (3/3) 32
33. Case Study — Tracing Overhead • A Zookeeper client performing 10k iterations of four operations: ◦ Check whether a znode exists ◦ Create a new znode ◦ Check again whether the znode exists ◦ Delete the created znode 33 Duration per iteration (ms)
34. • Logs collected with two distinct log levels enabled: ◦ INFO - 342 entries ◦ INFO + DEBUG - 568 entries Case Study — Constraint Solving Performance 34
35. Future Work • An eBPF-based tracer, which is expected to be much more efficient than ptrace-based tracing tools • An interactive space-time diagram ◦ Integration with ShiViz 35
36. Conclusions • Understanding distributed system behavior requires the ability to reason about the causality of events in different processes • Falcon eases the analysis of distributed system executions without requiring manual instrumentation: ◦ Infers causally-related activity atop commodity tracing tools ◦ Generates a space-time diagram ◦ Incurs tolerable overhead 36
37. Thank you for your attention! Try Falcon now: https://github.com/fntneves/falcon 37