[PPT] - Failure Sketching: A Technique for Automated Root Cause Diagnosis PowerPoint Presentation

SLIDE 1

Failure Sketching: A Technique for Automated Root Cause Diagnosis

f In-Production Failures

Baris Kasikci, Benjamin Schubert, Cristiano Pereira, Gilles Pokam, George Candea

SLIDE 2

Debugging In-Production Software Failures Today

2

SLIDE 3

Debugging In-Production Software Failures Today

2

SLIDE 4

Debugging In-Production Software Failures Today

2

#0 0x00007f51abae820b in raise (sig=11) at ../nptl/ sysdeps/unix/sysv/linux/pt-raise.c:37 #1 0x000000000042d289 in ap_buffered_log_writer (r=0x7f51a40053d0, handle=0x20eeba0, strs=0x7f51a4003578, strl=0x7f51a40035e8, nelts=14, len=82) at mod_log_config.c:1368 #2 0x000000000042b10d in config_log_transaction (r=0x7f51a40053d0, cls=0x20b9d50, default_format=0x20ee370) at mod_log_config.c:930 #3 0x000000000042aad6 in multi_log_transaction (r=0x7f51a40053d0) at mod_log_config.c:950 #4 0x000000000046cb2d in ap_run_log_transaction (r=0x7f51a40053d0) at protocol.c:1563 #5 0x0000000000436e81 in ap_process_request (r=0x7f51a40053d0) at http_request.c:312 #6 0x000000000042e9da in ap_process_http_connection (c=0x7f519c000b68) at http_core.c:293 #7 0x0000000000465cdd in ap_run_process_connection (c=0x7f519c000b68) at connection.c:85 #8 0x00000000004661f5 in ap_process_connection (c=0x7f519c000b68, csd=0x7f519c000a20) at connection.c:211 #9 0x0000000000451ba0 in process_socket (p=0x7f519c0009b8, sock=0x7f519c000a20, my_child_num=0, my_thread_num=0, bucket_alloc=0x7f51a4001348) at worker.c:632 #10 0x0000000000451221 in worker_thread (thd=0x210fa90, dummy=0x7f51a40008c0) at worker.c:946 #11 0x00007f51ac87c555 in dummy_worker (opaque=0x210fa90) at thread.c:127 #12 0x00007f51abae0182 in start_thread (arg=0x7f51aa8ef700) at pthread_create.c:312 #13 0x00007f51ab80d47d in clone () at ../sysdeps/ unix/sysv/linux/x86_64/clone.S:111

SLIDE 5

Debugging In-Production Software Failures Today

2

#0 0x00007f51abae820b in raise (sig=11) at ../nptl/ sysdeps/unix/sysv/linux/pt-raise.c:37 #1 0x000000000042d289 in ap_buffered_log_writer (r=0x7f51a40053d0, handle=0x20eeba0, strs=0x7f51a4003578, strl=0x7f51a40035e8, nelts=14, len=82) at mod_log_config.c:1368 #2 0x000000000042b10d in config_log_transaction (r=0x7f51a40053d0, cls=0x20b9d50, default_format=0x20ee370) at mod_log_config.c:930 #3 0x000000000042aad6 in multi_log_transaction (r=0x7f51a40053d0) at mod_log_config.c:950 #4 0x000000000046cb2d in ap_run_log_transaction (r=0x7f51a40053d0) at protocol.c:1563 #5 0x0000000000436e81 in ap_process_request (r=0x7f51a40053d0) at http_request.c:312 #6 0x000000000042e9da in ap_process_http_connection (c=0x7f519c000b68) at http_core.c:293 #7 0x0000000000465cdd in ap_run_process_connection (c=0x7f519c000b68) at connection.c:85 #8 0x00000000004661f5 in ap_process_connection (c=0x7f519c000b68, csd=0x7f519c000a20) at connection.c:211 #9 0x0000000000451ba0 in process_socket (p=0x7f519c0009b8, sock=0x7f519c000a20, my_child_num=0, my_thread_num=0, bucket_alloc=0x7f51a4001348) at worker.c:632 #10 0x0000000000451221 in worker_thread (thd=0x210fa90, dummy=0x7f51a40008c0) at worker.c:946 #11 0x00007f51ac87c555 in dummy_worker (opaque=0x210fa90) at thread.c:127 #12 0x00007f51abae0182 in start_thread (arg=0x7f51aa8ef700) at pthread_create.c:312 #13 0x00007f51ab80d47d in clone () at ../sysdeps/ unix/sysv/linux/x86_64/clone.S:111

Understand root cause

SLIDE 6

Debugging In-Production Software Failures Today

2

#0 0x00007f51abae820b in raise (sig=11) at ../nptl/ sysdeps/unix/sysv/linux/pt-raise.c:37 #1 0x000000000042d289 in ap_buffered_log_writer (r=0x7f51a40053d0, handle=0x20eeba0, strs=0x7f51a4003578, strl=0x7f51a40035e8, nelts=14, len=82) at mod_log_config.c:1368 #2 0x000000000042b10d in config_log_transaction (r=0x7f51a40053d0, cls=0x20b9d50, default_format=0x20ee370) at mod_log_config.c:930 #3 0x000000000042aad6 in multi_log_transaction (r=0x7f51a40053d0) at mod_log_config.c:950 #4 0x000000000046cb2d in ap_run_log_transaction (r=0x7f51a40053d0) at protocol.c:1563 #5 0x0000000000436e81 in ap_process_request (r=0x7f51a40053d0) at http_request.c:312 #6 0x000000000042e9da in ap_process_http_connection (c=0x7f519c000b68) at http_core.c:293 #7 0x0000000000465cdd in ap_run_process_connection (c=0x7f519c000b68) at connection.c:85 #8 0x00000000004661f5 in ap_process_connection (c=0x7f519c000b68, csd=0x7f519c000a20) at connection.c:211 #9 0x0000000000451ba0 in process_socket (p=0x7f519c0009b8, sock=0x7f519c000a20, my_child_num=0, my_thread_num=0, bucket_alloc=0x7f51a4001348) at worker.c:632 #10 0x0000000000451221 in worker_thread (thd=0x210fa90, dummy=0x7f51a40008c0) at worker.c:946 #11 0x00007f51ac87c555 in dummy_worker (opaque=0x210fa90) at thread.c:127 #12 0x00007f51abae0182 in start_thread (arg=0x7f51aa8ef700) at pthread_create.c:312 #13 0x00007f51ab80d47d in clone () at ../sysdeps/ unix/sysv/linux/x86_64/clone.S:111

Understand root cause Reproduce the failure

SLIDE 7

Debugging In-Production Software Failures Today

2

#0 0x00007f51abae820b in raise (sig=11) at ../nptl/ sysdeps/unix/sysv/linux/pt-raise.c:37 #1 0x000000000042d289 in ap_buffered_log_writer (r=0x7f51a40053d0, handle=0x20eeba0, strs=0x7f51a4003578, strl=0x7f51a40035e8, nelts=14, len=82) at mod_log_config.c:1368 #2 0x000000000042b10d in config_log_transaction (r=0x7f51a40053d0, cls=0x20b9d50, default_format=0x20ee370) at mod_log_config.c:930 #3 0x000000000042aad6 in multi_log_transaction (r=0x7f51a40053d0) at mod_log_config.c:950 #4 0x000000000046cb2d in ap_run_log_transaction (r=0x7f51a40053d0) at protocol.c:1563 #5 0x0000000000436e81 in ap_process_request (r=0x7f51a40053d0) at http_request.c:312 #6 0x000000000042e9da in ap_process_http_connection (c=0x7f519c000b68) at http_core.c:293 #7 0x0000000000465cdd in ap_run_process_connection (c=0x7f519c000b68) at connection.c:85 #8 0x00000000004661f5 in ap_process_connection (c=0x7f519c000b68, csd=0x7f519c000a20) at connection.c:211 #9 0x0000000000451ba0 in process_socket (p=0x7f519c0009b8, sock=0x7f519c000a20, my_child_num=0, my_thread_num=0, bucket_alloc=0x7f51a4001348) at worker.c:632 #10 0x0000000000451221 in worker_thread (thd=0x210fa90, dummy=0x7f51a40008c0) at worker.c:946 #11 0x00007f51ac87c555 in dummy_worker (opaque=0x210fa90) at thread.c:127 #12 0x00007f51abae0182 in start_thread (arg=0x7f51aa8ef700) at pthread_create.c:312 #13 0x00007f51ab80d47d in clone () at ../sysdeps/ unix/sysv/linux/x86_64/clone.S:111

Understand root cause Reproduce the failure

SLIDE 8

Related Work

3

Collaborative approaches
WER [SOSP’09], CBI [PLDI’05], CCI [OOPSLA’10]
Identifying differences of failing and successful runs
Delta debugging [TSE’02], Symbiosis [PLDI’15]
Record & replay, checkpointing
ODR [SOSP’09], Triage [SOSP’07]
Hardware support
PBI [ASPLOS’13], LBRA/LCRA [ASPLOS’14]

SLIDE 9

Related Work

3

Collaborative approaches
WER [SOSP’09], CBI [PLDI’05], CCI [OOPSLA’10]
Identifying differences of failing and successful runs
Delta debugging [TSE’02], Symbiosis [PLDI’15]
Record & replay, checkpointing
ODR [SOSP’09], Triage [SOSP’07]
Hardware support
PBI [ASPLOS’13], LBRA/LCRA [ASPLOS’14]

SLIDE 10

Contributions

4

SLIDE 11

Contributions

4

Goal: automate the manual detective work of debugging 

SLIDE 12

Contributions

4

Goal: automate the manual detective work of debugging 

Failure sketching

Complements in-house static analysis with in-production dynamic analysis Automatically and efficiently builds accurate failure sketches that show root causes of failures

SLIDE 13

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); ... }

Failure Sketch

5

1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Thread 2 Segfault Thread 1 cons(queue* f) { ... mutex_unlock(f->mut); }

SLIDE 14

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); ... }

Failure Sketch

5

1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Thread 2 Segfault Thread 1 cons(queue* f) { ... mutex_unlock(f->mut); }

SLIDE 15

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); ... }

Failure Sketch

5

1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Thread 2 Segfault Thread 1 cons(queue* f) { ... mutex_unlock(f->mut); }

SLIDE 16

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); ... }

Failure Sketch

5

1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Thread 2 Segfault Thread 1 cons(queue* f) { ... mutex_unlock(f->mut); }

SLIDE 17

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); ... }

Failure Sketch

5

1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Thread 2 Segfault Thread 1 cons(queue* f) { ... mutex_unlock(f->mut); }

SLIDE 18

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); ... }

Failure Sketch

5

1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Thread 2

Root cause

Segfault Thread 1 cons(queue* f) { ... mutex_unlock(f->mut); }

SLIDE 19

Failure Sketch Usage Model

6

#0 0x00007f51abae820b in raise (sig=11) at ../nptl/ sysdeps/unix/sysv/linux/pt-raise.c:37 #1 0x000000000042d289 in ap_buffered_log_writer (r=0x7f51a40053d0, handle=0x20eeba0, strs=0x7f51a4003578, strl=0x7f51a40035e8, nelts=14, len=82) at mod_log_config.c:1368 #2 0x000000000042b10d in config_log_transaction (r=0x7f51a40053d0, cls=0x20b9d50, default_format=0x20ee370) at mod_log_config.c:930 #3 0x000000000042aad6 in multi_log_transaction (r=0x7f51a40053d0) at mod_log_config.c:950 #4 0x000000000046cb2d in ap_run_log_transaction (r=0x7f51a40053d0) at protocol.c:1563 #5 0x0000000000436e81 in ap_process_request (r=0x7f51a40053d0) at http_request.c:312 #6 0x000000000042e9da in ap_process_http_connection (c=0x7f519c000b68) at http_core.c:293 #7 0x0000000000465cdd in ap_run_process_connection (c=0x7f519c000b68) at connection.c:85 #8 0x00000000004661f5 in ap_process_connection (c=0x7f519c000b68, csd=0x7f519c000a20) at connection.c:211 #9 0x0000000000451ba0 in process_socket (p=0x7f519c0009b8, sock=0x7f519c000a20, my_child_num=0, my_thread_num=0, bucket_alloc=0x7f51a4001348) at worker.c:632 #10 0x0000000000451221 in worker_thread (thd=0x210fa90, dummy=0x7f51a40008c0) at worker.c:946 #11 0x00007f51ac87c555 in dummy_worker (opaque=0x210fa90) at thread.c:127 #12 0x00007f51abae0182 in start_thread (arg=0x7f51aa8ef700) at pthread_create.c:312 #13 0x00007f51ab80d47d in clone () at ../sysdeps/ unix/sysv/linux/x86_64/clone.S:111

Understand root cause Reproduce the failure

SLIDE 20

Failure Sketch Usage Model

6

#0 0x00007f51abae820b in raise (sig=11) at ../nptl/ sysdeps/unix/sysv/linux/pt-raise.c:37 #1 0x000000000042d289 in ap_buffered_log_writer (r=0x7f51a40053d0, handle=0x20eeba0, strs=0x7f51a4003578, strl=0x7f51a40035e8, nelts=14, len=82) at mod_log_config.c:1368 #2 0x000000000042b10d in config_log_transaction (r=0x7f51a40053d0, cls=0x20b9d50, default_format=0x20ee370) at mod_log_config.c:930 #3 0x000000000042aad6 in multi_log_transaction (r=0x7f51a40053d0) at mod_log_config.c:950 #4 0x000000000046cb2d in ap_run_log_transaction (r=0x7f51a40053d0) at protocol.c:1563 #5 0x0000000000436e81 in ap_process_request (r=0x7f51a40053d0) at http_request.c:312 #6 0x000000000042e9da in ap_process_http_connection (c=0x7f519c000b68) at http_core.c:293 #7 0x0000000000465cdd in ap_run_process_connection (c=0x7f519c000b68) at connection.c:85 #8 0x00000000004661f5 in ap_process_connection (c=0x7f519c000b68, csd=0x7f519c000a20) at connection.c:211 #9 0x0000000000451ba0 in process_socket (p=0x7f519c0009b8, sock=0x7f519c000a20, my_child_num=0, my_thread_num=0, bucket_alloc=0x7f51a4001348) at worker.c:632 #10 0x0000000000451221 in worker_thread (thd=0x210fa90, dummy=0x7f51a40008c0) at worker.c:946 #11 0x00007f51ac87c555 in dummy_worker (opaque=0x210fa90) at thread.c:127 #12 0x00007f51abae0182 in start_thread (arg=0x7f51aa8ef700) at pthread_create.c:312 #13 0x00007f51ab80d47d in clone () at ../sysdeps/ unix/sysv/linux/x86_64/clone.S:111

Understand root cause Reproduce the failure

SLIDE 21

Failure Sketch Usage Model

6

#0 0x00007f51abae820b in raise (sig=11) at ../nptl/ sysdeps/unix/sysv/linux/pt-raise.c:37 #1 0x000000000042d289 in ap_buffered_log_writer (r=0x7f51a40053d0, handle=0x20eeba0, strs=0x7f51a4003578, strl=0x7f51a40035e8, nelts=14, len=82) at mod_log_config.c:1368 #2 0x000000000042b10d in config_log_transaction (r=0x7f51a40053d0, cls=0x20b9d50, default_format=0x20ee370) at mod_log_config.c:930 #3 0x000000000042aad6 in multi_log_transaction (r=0x7f51a40053d0) at mod_log_config.c:950 #4 0x000000000046cb2d in ap_run_log_transaction (r=0x7f51a40053d0) at protocol.c:1563 #5 0x0000000000436e81 in ap_process_request (r=0x7f51a40053d0) at http_request.c:312 #6 0x000000000042e9da in ap_process_http_connection (c=0x7f519c000b68) at http_core.c:293 #7 0x0000000000465cdd in ap_run_process_connection (c=0x7f519c000b68) at connection.c:85 #8 0x00000000004661f5 in ap_process_connection (c=0x7f519c000b68, csd=0x7f519c000a20) at connection.c:211 #9 0x0000000000451ba0 in process_socket (p=0x7f519c0009b8, sock=0x7f519c000a20, my_child_num=0, my_thread_num=0, bucket_alloc=0x7f51a4001348) at worker.c:632 #10 0x0000000000451221 in worker_thread (thd=0x210fa90, dummy=0x7f51a40008c0) at worker.c:946 #11 0x00007f51ac87c555 in dummy_worker (opaque=0x210fa90) at thread.c:127 #12 0x00007f51abae0182 in start_thread (arg=0x7f51aa8ef700) at pthread_create.c:312 #13 0x00007f51ab80d47d in clone () at ../sysdeps/ unix/sysv/linux/x86_64/clone.S:111

Understand root cause Runtime traces Reproduce the failure

SLIDE 22

Failure Sketch Usage Model

6

Understand root cause

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); ... } cons(queue* f) { ... mutex_unlock(f->mut); } 1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Failure: segmentation fault Thread 1 Thread 2

Runtime traces Reproduce the failure

SLIDE 23

Failure Sketch Usage Model

6

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); ... } cons(queue* f) { ... mutex_unlock(f->mut); } 1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Failure: segmentation fault Thread 1 Thread 2

Runtime traces

SLIDE 24

Failure Sketch Usage Model

6

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); ... } cons(queue* f) { ... mutex_unlock(f->mut); } 1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Failure: segmentation fault Thread 1 Thread 2

Runtime traces

SLIDE 25

Outline

Challenges
Design
Evaluation

7

SLIDE 26

Outline

Challenges
Design
Evaluation

7

SLIDE 27

Challenges of Building Failure Sketches

Accuracy
Exclude all irrelevant information, preserve all relevant one
Recurrence
Gathering enough execution information from rare failures
Latency
Achieve high accuracy after just a few recurrences

8

SLIDE 28

Outline

Challenges
Design

9

Evaluation

SLIDE 29

Outline

Challenges
Design

9

Evaluation

Static Analysis Control and Data Flow Tracking Statistical Analysis Failure sketch

SLIDE 30

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); ... } cons(queue* f) { ... mutex_unlock(f->mut); } 1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Failure: segmentation fault Thread 1 Thread 2

Gist System Architecture

10

Runtime traces

SLIDE 31

Client Server

Gist System Architecture

10

SLIDE 32

Client Server

Gist System Architecture

10

Program P (source) Failure report (core dump, stack trace, etc)

1

SLIDE 33

Client Server

Gist System Architecture

10

Program P (source) Failure report (core dump, stack trace, etc)

1

Static Analyzer

queue* f = init(size);
init_vars();
free(f->mut);
print(“Done”);
f->mut = NULL;

Static slice

SLIDE 34

Client Server

Gist System Architecture

10

Program P (source) Failure report (core dump, stack trace, etc)

1

Static Analyzer

2

Instrumentation Tracking control and data flow

queue* f = init(size);
init_vars();
free(f->mut);
print(“Done”);
f->mut = NULL;

Static slice

SLIDE 35

Client Server

Gist System Architecture

10

Program P (source) Failure report (core dump, stack trace, etc)

1

Static Analyzer

2

Instrumentation

3

Refinement with runtime traces Tracking control and data flow

queue* f = init(size);
init_vars();
free(f->mut);
print(“Done”);
f->mut = NULL;

Static slice

SLIDE 36

Client Server

Gist System Architecture

10

Program P (source) Failure report (core dump, stack trace, etc)

1

Static Analyzer

2

Instrumentation

3

Refinement with runtime traces Tracking control and data flow

queue* f = init(size);
init_vars();
free(f->mut);
print(“Done”);
f->mut = NULL;

Static slice Refined static slice

SLIDE 37

Client Server

Gist System Architecture

10

Program P (source) Failure report (core dump, stack trace, etc)

1

Static Analyzer

2

Instrumentation

3

Refinement with runtime traces Failure Sketch Computation Engine

4

Tracking control and data flow

queue* f = init(size);
init_vars();
free(f->mut);
print(“Done”);
f->mut = NULL;

Static slice

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); f->mut = NULL; ... } cons(queue* f) { ... mutex_unlock(f->mut); } 1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Failure: segmentation fault Thread 1 Thread 2

Failure Sketch Refined static slice

SLIDE 38

Outline

11

Challenges
Design
Evaluation

Static Analysis Control and Data Flow Tracking Statistical Analysis Failure sketch

SLIDE 39

Outline

11

Challenges
Design
Evaluation

Static Analysis Control and Data Flow Tracking Statistical Analysis Failure sketch

SLIDE 40

12

Static Analysis to Reduce the Overhead

Computes backward slices
Includes statements with dependencies to the failure
Excludes all other statements
Inter-procedural
Identify dependencies across functions

SLIDE 41

12

Static Analysis to Reduce the Overhead

Computes backward slices
Includes statements with dependencies to the failure
Excludes all other statements
Inter-procedural
Identify dependencies across functions

Static analysis reduces subsequent runtime tracking (20x)

SLIDE 42

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

13

Example

SLIDE 43

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

13

Example

SLIDE 44

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

13

Example

SLIDE 45

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

13

Example

SLIDE 46

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

13

Example

SLIDE 47

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

13

Example

Segfault

SLIDE 48

14

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Example

Segfault

SLIDE 49

15

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Example: Static Backward Slicing

Segfault

SLIDE 50

Outline

16

Challenges
Design
Evaluation

Static Analysis Control and Data Flow Tracking Statistical Analysis Failure sketch

SLIDE 51

Outline

16

Challenges
Design
Evaluation

Static Analysis Control and Data Flow Tracking Statistical Analysis Failure sketch

SLIDE 52

Low-Overhead Control Flow Tracking

Software-based tracking is expensive (up to 15x)
Hardware-based tracking is more efficient
Intel PT: new feature in Intel CPUs (~40%)
Gist combines static analysis and hardware-based

control flow tracking

Low overhead (~2%)

17

SLIDE 53

Low-Overhead Control Flow Tracking

Software-based tracking is expensive (up to 15x)
Hardware-based tracking is more efficient
Intel PT: new feature in Intel CPUs (~40%)
Gist combines static analysis and hardware-based

control flow tracking

Low overhead (~2%)

17

Static analysis → Low-overhead control flow tracking

SLIDE 54

Example: Control Flow Tracking (Step 1)

18

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Segfault

SLIDE 55

19

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Example: Control Flow Tracking (Step 2)

Segfault

SLIDE 56

19

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Example: Control Flow Tracking (Step 2)

Static analysis + control flow tracking shorten the sketch

Segfault

SLIDE 57

20

Data Flow Tracking to Increase Accuracy

SLIDE 58

Data flow information
Variable values & total order of memory accesses

20

Data Flow Tracking to Increase Accuracy

SLIDE 59

Data flow information
Variable values & total order of memory accesses
Hardware watchpoints
Allow tracking reads and writes with low overhead
Allow tracking the total order of accesses

20

Data Flow Tracking to Increase Accuracy

SLIDE 60

Data flow information
Variable values & total order of memory accesses
Hardware watchpoints
Allow tracking reads and writes with low overhead
Allow tracking the total order of accesses
Monitor multiple clients when run out of watchpoints

20

Data Flow Tracking to Increase Accuracy

SLIDE 61

Data flow information
Variable values & total order of memory accesses
Hardware watchpoints
Allow tracking reads and writes with low overhead
Allow tracking the total order of accesses
Monitor multiple clients when run out of watchpoints

20

Data Flow Tracking to Increase Accuracy

Precise ordering information → High accuracy

SLIDE 62

21

void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); } void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; }

Segfault

Example: Data Flow Tracking

SLIDE 63

21

void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); } void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; }

Segfault

Watch &s

Example: Data Flow Tracking

SLIDE 64

22

void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); } void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; }

Example: Data Flow Tracking

Segfault

Watch &s

SLIDE 65

22

void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); } void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; }

Success

Example: Data Flow Tracking

Thread 1 Thread 2

SLIDE 66

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

22

void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); } void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; }

Success

Example: Data Flow Tracking

Thread 1 Thread 2

SLIDE 67

Outline

23

Challenges
Design
Evaluation

Static Analysis Control and Data Flow Tracking Statistical Analysis Failure sketch

SLIDE 68

Outline

23

Challenges
Design
Evaluation

Static Analysis Control and Data Flow Tracking Statistical Analysis Failure sketch

SLIDE 69

24

Statistical Analysis

SLIDE 70

Identification of failure predictors1
A good predictor portends a failure with high probability

(e.g., data races, atomicity violations)

24

Statistical Analysis

1 Liblit, B. et al. Scalable sta0s0cal bug isola0on. PLDI 2005

SLIDE 71

Identification of failure predictors1
A good predictor portends a failure with high probability

(e.g., data races, atomicity violations)

Example: data races

24

Statistical Analysis

1 Liblit, B. et al. Scalable sta0s0cal bug isola0on. PLDI 2005

write x write x write x read x read x write x

SLIDE 72

Identification of failure predictors1
A good predictor portends a failure with high probability

(e.g., data races, atomicity violations)

Example: data races

24

Statistical Analysis

1 Liblit, B. et al. Scalable sta0s0cal bug isola0on. PLDI 2005

write x write x write x read x read x write x

Failure predictors across multiple executions

SLIDE 73

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

25 25

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; }

Success

void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Example: Statistical Analysis

SLIDE 74

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

25 25

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; }

Success

void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); } void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

Example: Statistical Analysis

SLIDE 75

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

25 25

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; }

Success

void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); } void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

Example: Statistical Analysis

SLIDE 76

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

25 25

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; }

Success

void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); } void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

Example: Statistical Analysis

write read

SLIDE 77

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

25 25

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; }

Success

void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); } void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Failure

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

void cleanup(State* s) { log(“Func:cleanup”); if(verbose) log(“Cleaning up %p”, s); delete s; } void display_size(State* s) { log(“Func:display_size”); log(“State: %u”, s->size); }

Success

Static analysis + cooperative dynamic analysis

Example: Statistical Analysis

write read

SLIDE 78

Outline

26

Challenges
Design
Evaluation

Static Analysis Control and Data Flow Tracking Statistical Analysis Failure sketch

SLIDE 79

Outline

26

Challenges
Design
Evaluation
Does Gist help developers do root cause diagnosis?
Is Gist efficient?
Is Gist accurate?

SLIDE 80

27

Client side executions are analyzed in the lab
Real world server and desktop programs

memcached

Experimental Setup

SLIDE 81

Do Failure Sketches Help Developers?

We manually analyzed the usefulness of Gist for 11

failures

Gist-identified failure predictors point to root causes
Developers eliminated those root causes to fix the bugs
Average number of statements to look at: 7

28

SLIDE 82

Do Failure Sketches Help Developers?

We manually analyzed the usefulness of Gist for 11

failures

Gist-identified failure predictors point to root causes
Developers eliminated those root causes to fix the bugs
Average number of statements to look at: 7

Gist points developers to the root causes of failures

28

SLIDE 83

1 2 3 4 5 5 10 15 20 25

# of statements tracked Performance

verhead [%]

Efficiency

29

(Control & data flow tracking)

SLIDE 84

1 2 3 4 5 5 10 15 20 25

# of statements tracked Performance

verhead [%]

Gist has low average overhead (always below 5%)

Efficiency

29

(Control & data flow tracking)

SLIDE 85

30

Accuracy [%] Apache-1 Apache-2 Apache-3 Apache-4 Cppcheck-1 Cppcheck-2 Curl Transmission SQLite memcached Pbzip2

Accuracy

SLIDE 86

30

0.0 25.0 50.0 75.0 100.0

Accuracy [%] Apache-1 Apache-2 Apache-3 Apache-4 Cppcheck-1 Cppcheck-2 Curl Transmission SQLite memcached Pbzip2

Accuracy

SLIDE 87

30

0.0 25.0 50.0 75.0 100.0

Static slicing Accuracy [%] Apache-1 Apache-2 Apache-3 Apache-4 Cppcheck-1 Cppcheck-2 Curl Transmission SQLite memcached Pbzip2

Accuracy

SLIDE 88

30

0.0 25.0 50.0 75.0 100.0

Control flow tracking Static slicing Accuracy [%] Apache-1 Apache-2 Apache-3 Apache-4 Cppcheck-1 Cppcheck-2 Curl Transmission SQLite memcached Pbzip2

Accuracy

SLIDE 89

30

0.0 25.0 50.0 75.0 100.0

Control flow tracking Data flow tracking Static slicing Accuracy [%] Apache-1 Apache-2 Apache-3 Apache-4 Cppcheck-1 Cppcheck-2 Curl Transmission SQLite memcached Pbzip2

Accuracy

SLIDE 90

30

0.0 25.0 50.0 75.0 100.0

Control flow tracking Data flow tracking Static slicing Accuracy [%] Apache-1 Apache-2 Apache-3 Apache-4 Cppcheck-1 Cppcheck-2 Curl Transmission SQLite memcached Pbzip2

Accuracy

Average accuracy is 96%

SLIDE 91

30

0.0 25.0 50.0 75.0 100.0

Control flow tracking Data flow tracking Static slicing Accuracy [%] Apache-1 Apache-2 Apache-3 Apache-4 Cppcheck-1 Cppcheck-2 Curl Transmission SQLite memcached Pbzip2

Each technique is needed for accuracy

Accuracy

Average accuracy is 96%

SLIDE 92

Failure sketching
Combination of static and dynamic program

analysis

Failure sketches are summaries explaining failure

root causes

Accurate, efficient, improves developer productivity

31

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); f->mut = NULL; ... } cons(queue* f) { ... mutex_unlock(f->mut); } 1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Failure: segmentation fault Thread 1 Thread 2

Conclusion

SLIDE 93

Failure sketching
Combination of static and dynamic program

analysis

Failure sketches are summaries explaining failure

root causes

Accurate, efficient, improves developer productivity

31

main() { queue* f = init(size); create_thread(cons, f); ... free(f->mut); f->mut = NULL; ... } cons(queue* f) { ... mutex_unlock(f->mut); } 1 2 3 4 5 6 7 8 1 2 3 4 5 6 7 8 Time Failure: segmentation fault Thread 1 Thread 2

Conclusion

Cristiano Baris Ben Gilles George