Dr Debug Deterministic Replay based Cyclic Debugging with

Dr. Debug: Deterministic Replay based Cyclic Debugging with Dynamic Slicing Yan Wang*, Harish Patil**, Cristiano Pereira**, Gregory Lueck**, Rajiv Gupta*, and Iulian Neamtiu* *University of California Riverside **Intel Corporation 1

Cyclic Debugging for Multi-threaded Programs ver. 1. 9. 1 Root cause of the bug? Mozilla developer Bug report Id: 515403 Program binary + input Fast-forward to the buggy region Data race on variable rt->script. Filename. Table main thread Fast Forward buggy Region worker threads T 1 T 2 • Long wait while fast-forwarding (88%) • Observe program state Buggy region (12%) still large: ~1 M instructions Difficult to locate the bug 2

Key Contributions of Dr. Debug Execution Region and Execution Slice T 1 T 2 Region v User Selects Execution Region Ø Only capture execution of buggy region Ø Avoid fast forwarding v User Examines Execution Slice Ø Only capture bug related execution Ø Work for multi-threaded programs Ø Single-step slice in a live debugging session Results: • Buggy region: <15% of total execution for bugs in 3 real-world programs • Execution slice: < 48% of buggy region, < 7% of total execution for bugs in 3 real-world programs 3

Pin. Play in Dr. Debug Pin. Play [Patil et. al. , CGO’ 10, http: //www. pinplay. org] is a record/replay system, using the Pin dynamic instrumentation system. Program binary + input Logger region pinball Captures the non-deterministic events of the execution of a (buggy) region pinball Replayer Program Output Deterministically repeat the captured execution region pinball Relogger pinball Relog execution—exclude the execution of some code regions 4

Execution Region T 1 T 2 Record on Region Record off Failure Point Root Cause region pinball 5

Dynamic Slicing Dynamic slice: executed statements that played a role in the computation of the value. T 1 T 2 region pinball Root Cause compute slice Failure Point 6

Dynamic Slicing Dynamic slice: executed statements that played a role in the computation of the value. T 1 T 2 region pinball Root Cause compute slice pinball Failure Point Excluded Code Region 7

Replaying Execution Slice T 1 T 2 Prior work on slicing: post-mortem analysis slice pinball Inject value Failure Point 8

Usage model of Dr. Debug record on/off compute slice Dr. Debug slice pinball Program binary + input Only Capture Bug Related Program Execution Root cause of the bug? Cyclic Debugging Based on Replay of Execution Slice Observe program state 9

Other Contributions v Improve Precision of Dynamic Slice Ø Dynamic Data Dependence Precision • Filter out spurious register dependences due to save/restore pairs at the entry/exit of each function Ø Dynamic Control Dependence Precision • Presence of Indirect jumps Inaccurate CFG Missing Control Dependence • Refine CFG with dynamically collected jump targets v Integration with Maple [Yu et al. OOPSLA’ 12] • Capture exposed buggy execution into pinball • Debug exposed concurrency bug with Dr. Debug 10

Dr. Debug GUI Showing a Dynamic Slice Criterion 11

Data Race bugs used in our Case Studies Program Name Bug Description pbzip 2 -0. 9. 4 A data race on variable fifo mut between main thread and the compressor threads Aget-0. 57 A data race on variable bwritten between downloader threads and the signal handler thread Mozilla-1. 9. 1 A data race on variable rt script. Filename. Table. One thread destroys a hash table, and another thread crashes in js_Sweep. Script. Filenames when accessing this hash table • Quantify the buggy execution region size for real bugs. • Time and space overhead of Dr. Debug are reasonable for real bugs. 12

Time and Space Overheads for Data Race Bugs with Buggy Execution Region Program Name #ins(%ins in region vs. total) #ins in slice pinball (%ins in slice vs. region pinball) Logging Overhead Pbzip 2 (0. 9. 4) 11, 186 (0. 04%) 1, 065 (9. 5%) 5. 7 0. 7 1. 5 0. 01 Aget (0. 57) 108, 695 (14. 3%) 51, 278(47. 2%) 8. 4 0. 6 3. 9 0. 02 Mozilla (1. 9. 1) 999, 997 (12. 2%) 100 (0. 01%) 9. 9 1. 1 3. 6 1. 2 Time (sec) Space (MB) Replay Time (sec) Slicing Time (sec) • Buggy region size ~ 1 M • Buggy Region: <15% of total execution • Execution Slice: <48% of buggy region, <7% of total execution 13

Logging Time Overheads PARSEC 4 T runs: Region logging time in seconds 250 237 202 200 158 144 150 129 120 100 59 2 89 44 46 1 44 34 25 12 75 71 47 50 106 97 84 125 9 1 7 23 33 37 31 11 7 2 6 29 10 e ag er clu m st re a Av st e r p du de l ea ca nn s vip ns tio sw m ni id a ap at e ck bo dy tra flu bl ac ks ch ol es 0 log: 10 M log: 100 M log: 500 M log: 1 B with native input 14

Replay Time Overheads PARSEC: 4 T Region pinballs: Replay time in seconds 160 142 132 140 120 105 100 83 80 The buggy regions up to a billion instructions can still 55 60 52 44 43 be 37 collected/replayed in reasonable time(~2 min). 35 35 34 60 40 29 29 19 20 1 16 5 3 28 17 7 5 1 1 4 18 12 8 2 2 5 27 11 replay: 10 M ag e Av er st re am clu st er p de du al ca nn e ps vi ns ap sw an i m tio at e ck tra dy bo flu id bl ac ks ch ol es 0 replay: 100 M replay: 500 M replay: 1 B with native input 15

Execution Slice: replay time PARSEC: (4 T) Region and Slice pinballs: Replay time in seconds 5. 0 4. 0 3. 0 2. 30 2. 10 2. 0 1. 76 0. 99 1. 0 Average instruction count for slice pinball 4. 40 4. 36 (% of region ) : blackscholes: 22% bodytrack: 32% 3. 40 fludanimate: 23% swaptions: 10% vips: 81% canneal: 99% dedup: 30% streamcluster: 27% Average : 41% 1. 23 2. 10 0. 36 36% 1. 23 0. 70 0. 30 0. 19 1. 95 0. 69 0. 30 e ag er clu m st re a Av st er p du de l ea nn ca ps vi ns ap sw im an id tio at e ck bo dy tra flu bl ac ks ch ol es 0. 0 region-replaytime: 1 M avg-slice-replaytime: 1 M with native input 16

Contributions • Support for recording: execution regions and dynamic slices • Execution of dynamic slices for improved bug localization and replay efficiency • Backward navigation of a dynamic slice along dependence edges with Kdbg based GUI • Results: Buggy region: <15% of total execution; Execution slice: <48% of buggy region, <7% of total execution for bugs in 3 real-world programs Replay-based debugging and slicing is practical if we focus on a buggy region 17

Q&A? 18

Backup 19

Cyclic Debugging with Dr. Debug Program binary + input Logger (w/ fast forward) pinball Replayer Capture Buggy Region Pin’s Debugger Interface (Pin. ADX) Replay-based Cyclic Debugging Form/Refine a hypothesis about the cause of the bug Observe program state/ reach failure 20

Dynamic Slicing in Dr. Debug when Integrated with Pin. Play Pin Program binary + input region pinball logger (a) Capture buggy region. Pin KDbg Replayer Remote Debugging Protocol GDB region pinball Dynamic Slicing slice (b) Replay buggy Region and Compute Dynamic Slices. 21

Dynamic Slicing in Dr. Debug when Integrated with Pin. Play slice Pin + Relogger region pinball slice pinball (c) Generate Slice Pinball from Region Pinball. Pin KDbg Replayer GDB slice pinball Remote Debugging Protocol (d) Replay Execution Slice and Debug by Examining State. 22

Computing Dynamic Slicing for Multi-threaded Programs v Collect Per Thread Local Execution Traces v Construct the Combined Global Trace • Shared Memory Access Order • Topological Order v Compute Dynamic Slice by Backwards Traversing the Global Trace • Adopted Limited Preprocessing (LP) algorithm [Zhang et al. , ICSE’ 03] to speed up the traversal of the trace 23

Dynamic Slicing a Multithreaded Program Def-Use Trace for T 1 Def-Use Trace for T 2 11 {x} {} int x, y, z; T 1 1 2 3 4 5 6 x=5; z=x; int w=y; w=w-2; int m=3*x; x=m+2; 7 8 9 10 11 12 13 wrongly assumed atomic region Example Code 71 {y} {} y 21 {z} {x} T 2 y=2; int j=y + 1; j=z + j; int k=4*y; if (k>x){ k=k-x; assert(k>0); } 31 {w} {y} z 41 {w}{w} x 101 {k} {y} 51 {m} {x} 111 {k, x} {} 61 {x} {m} x 81 {j} {y} x x 91 {j} {z, j} 121 {k}{k, x} program order shared memory 131 {k} {} access order fox x Per Thread Traces and Shared Memory Access Order 24

Dynamic Slicing a Multithreaded Program {y} {} {j} {y} {j} {z, j} T 2 {k} {y} {k, x} {} {w} {y} {w} T 1 {m} {x} {m} {k, x} T 2 {k} {} Global Trace 11 x=5 71 51 m=3*x y=2 m y 61 x=m+2 101 k=4*y k 111 if(k>x) x T 1 x 71 81 91 101 111 31 41 51 61 121 131 {} {x} x 11 {x} 21 {z} CD root cause 121 k=k-x k should read (depend on) the same definition of x CD 131 assert(k>0) slice criterion Slice for k at 131 25

Execution Slice Example v. Prior works-- postmortem analysis v. Execution Slice – single-stepping/examining slice in a live debugging session T 1 11 x=5 21 31 41 T 2 71 y=2 T 1 11 x=5 T 2 71 y=2 inject 81 j=y +1 Only Bug Related Executions (e. g. , root cause, z=x z=5 9 j=z + j w=yfailure 1 point) are Replayed and Examined to w=0 101 k=4*y 51 m=3*x w=w-2 10 Understand 1 k=4*y and Locate bugs. 11 if (k>x) 6 x=m+2 51 m=3*x 61 x=m+2 111 if (k>x) 121 k=k-x 131 assert(k>0) Code Exclusion Regions 1 inject j=8 1 121 k=k-x 131 assert(k>0) Injecting Values During Replay 26

Control Dependences in the Presence of indirect jump 1 P(FILE* fin, int d){ 2 int w; 3 char c=fgetc(fin); 4 switch(c){ 5 case 'a': /* slice criterion */ 6 w = d + 2; Inaccurate CFG 7 break; Causing 8 … Missed Control 11} Dependence C Code 61 : w=d+2 Imprecise Slice for w at line 61 3 call fgetc mov %al, 0 x 9(%ebp) 4. . . mov 0 x 8048708(, %eax, 4), %eax jmp *%eax 6 mov 0 xc(%ebp), %eax add $0 x 2, %eax mov %eax, -0 x 10(%ebp) 7 jmp 80485 c 88. . . Assembly Code 31: c=fgetc(fin) ‘a’ c 41: switch(c) Capture Missing Control Dependence due to indirect jump CD 61 : w=d+2 27

Improve Dynamic Control Dependence Precision v Implement a static analyzer based on Pin's static code discovery library -- this allows Dr. Debug to work with any x 86 or Intel 64 binary. v We construct an approximate static CFG and as the program executes, we collect the dynamic jump targets for the indirect jumps and refine the CFG by adding the missing edges. v The refined CFG is used to compute the immediate postdominator for each basic block 28

Spurious Dependences Example 1 2 3 4 5 6 7 8 9 10 11 12 P(FILE* fin, int d){ int w, e; char c=fgetc(fin); e= d + d; if(c=='t') Q(); w=e; /* slice criterion */ } Q() {. . . } C Code save/restore pair 3 call fgetc mov %al, -0 x 9(%ebp) 4 mov 0 xc(%ebp), %eax add %eax, %eax 5 cmpb $0 x 74, -0 x 9(%ebp) jne 804852 d 6 call Q 804852 d 7 mov %eax, -0 x 10(%ebp) 9 Q() 10 push %eax save/restore. . . pair 12 pop %eax Assembly Code Spurious Data/Control Dependence 29

Spurious Dependences Example True Definition of eax ‘t’ 31: c=fgetc(fin) c 51: if(c==‘t’) 41: e = d+d add %eax, %eax e CD 101: push %eax CD 121: pop %eax 71 : w=e mov %eax, -0 x 10(%ebp) Imprecise Slice for w at line 71 Bypass data dependences caused by save/restore pairs 41: e = d+d add %eax, %eax e 71 : w=e mov %eax, -0 x 10(%ebp) Refined Slice 30

Improved Dynamic Dependence Precision v Dynamic Control Dependence Precision • Indirect jump (switch-case statement): Inaccurate CFG missing Control Dependence • Refine CFG with dynamically collected jump targets v Dynamic Data Dependence Precision • Spurious dependence caused by save/restore pairs at the entry/exit of each function • Identify save/restore pairs and bypass data dependences 31

Integration with Maple v Maple [Yu et al. OOPSLA’ 12] is a thread interleaving coverage-driven testing tool. Maple exposes untested thread interleaving as much as possible. v We changed Maple to optionally do Pin. Play-based logging of the buggy execution it exposes. v We have successfully recorded multiple buggy executions and replayed them using Dr. Debug. 32

Slicing Time Overhead v 10 slices for the last 10 different read instructions, spread across five threads, for region length 1 M (main thread) v Average dynamic information tracing time: 51 seconds v Average size of slice: 218 K dynamic instructions v. Average slicing time: 585 seconds 33

Dynamic Slicer Implementation Pin Immediate Post Dominators + Shared Memory Access Order Control Dependence Detection Global Trace Construction Slicer & Code Exclusion Regions Builder 34

Time and Space Overheads for Data Race Bugs with Whole Execution Region Program Name pbzip 2 Aget Mozilla #executed ins #ins in slice pinball (%ins in slice pinball) Logging Overhead Time (sec) Space (MB) Replay Time (sec) Slicing Time (sec) 30, 260, 300 11, 152 (0. 04%) 12. 5 1. 3 8. 2 1. 6 761, 592 79, 794 (10. 5%) 10. 5 1. 0 10. 1 52. 6 8, 180, 858 813, 496 (9. 9%) 21. 0 2. 1 19. 6 3, 200. 4 35

Logging Time Overheads PARSEC 4 T runs: Region logging time in seconds 250 200 150 237 Average region (all threads) instruction count : log: 10 M : 37 million log: 100 M: 541 million log: 500 M: 2. 3 billion log: 1 B : 4. 5 billion 202 158 144 129 120 100 59 2 89 44 46 1 44 34 25 12 75 71 47 50 106 97 84 125 9 1 7 23 33 37 31 11 7 2 6 29 10 e ag er clu m st re a Av st e r p du de l ea ca nn s vip ns tio sw m ni id a ap at e ck bo dy tra flu bl ac ks ch ol es 0 log: 10 M log: 100 M log: 500 M log: 1 B 36

Replay Time Overheads PARSEC: 4 T Region pinballs: Replay time in seconds 160 142 132 Average pinball sizes: log: 10 M : 23 MB log: 100 M: 56 MB log: 500 M: 86 MB log: 1 B : 105 MB 120 100 80 105 83 52 60 44 37 40 29 19 20 1 16 5 3 35 29 34 7 5 1 1 4 18 12 8 2 2 5 55 43 35 28 17 60 27 11 replay: 10 M ag e Av er st re am clu st er p de du al ca nn e ps vi ns ap sw an i m tio at e ck tra dy bo flu id bl ac ks ch ol es 0 replay: 100 M replay: 500 M replay: 1 B 37

Removal of Spurious Dependences: slice sizes SPECOMP 4 T runs: Average percent of reduction in slice sizes 35 slice: 1 M 29. 76 30 slice: 10 M 25 20 15. 48 15 11. 4 10 9. 49 8. 53 6. 31 5 1. 12 1. 97 2. 92 3. 6 2. 24 1. 95 0 mgrid_m wupwise_m ammp_m apsi_m galgel_m Average 38