[Sheepdog] [PATCH v2] Add a ftrace-like trace utility

[Liu Yuan]

v2:
 - use ring buffer for trace output
 - add a cat operation for collie

This patch set aims to provide a ftrace-like trace utility for performance tuning 
of online system in production environment. This means virtually no overhead when
disabled.

The patch set achieves this by dynamically patching the binary code at runtime, making
use of GCC -pg instrumentation features, which instrument a 5-bytes opcode in every function.

When the trace is
 turned off, the opcode is patched as NOP opcode.
 turned on, the opcode is a call opcode to our trace functions and we can hook callbacks both for
function entry and exit. This is how the patch atually calculate the time spent by function.

I use the below script[*] to get the following output:
---------------------------------------------------------
tailai.ly at taobao:~/sheepdog$ ./test3.sh "-b farm"
using backend farm store
Formatting 'sheepdog:test', fmt=raw size=1073741824 
wrote 10485760/10485760 bytes at offset 0
10 MiB, 1 ops; 0.8899 sec (11.237 MiB/sec and 1.1237 ops/sec)
read 10485760/10485760 bytes at offset 0
10 MiB, 1 ops; 0.5130 sec (19.492 MiB/sec and 1.9492 ops/sec)

Begin tracing

wrote 10485760/10485760 bytes at offset 10485760
10 MiB, 1 ops; 0.8662 sec (11.544 MiB/sec and 1.1544 ops/sec)
read 10485760/10485760 bytes at offset 10485760
10 MiB, 1 ops; 0.5425 sec (18.431 MiB/sec and 1.8431 ops/sec)

Cat the trace buffer

   Time(us)  |  Function Graph
-------------------------------
             |  do_io_request() {
             |     forward_write_obj_req() {
             |        addr_to_str() {
       2.132 |        }
             |        get_sheep_fd() {
      29.960 |        }
             |        send_req() {
    1538.482 |        }
             |        addr_to_str() {
       5.644 |        }
             |        addr_to_str() {
       0.598 |        }
             |        get_sheep_fd() {
      25.426 |        }
             |        send_req() {
    4184.318 |        }
             |        do_local_io() {
             |           do_process_work() {
             |              store_write_obj() {
             |                 farm_open() {
             |                    strbuf_add() {
             |                       strbuf_grow() {
             |                          xrealloc() {
       0.786 |                          }
       1.625 |                       }
       2.555 |                    }
             |                    strbuf_addf() {
             |                       strbuf_grow() {
             |                          xrealloc() {
       1.636 |                          }
       1.894 |                       }
       4.325 |                    }
             |                    strbuf_release() {
       0.98  |                    }
      31.288 |                 }
             |                 do_write_obj() {
             |                    farm_write() {
             |                       xpwrite() {
  234185.848 |                       }
             |                       trunk_update_entry() {
             |                          lookup_trunk_entry() {
       0.691 |                          }
       2.784 |                       }
  234194.492 |                    }
  234195.533 |                 }
             |                 farm_close() {
       6.697 |                 }
  234237.173 |              }
  234238.461 |           }
  234260.257 |        }
             |        do_read() {
       8.18  |        }
             |        do_read() {
       9.308 |        }
  406753.259 |     }
  406774.40  |  }
...

[*]
#!/bin/bash

pkill -9 sheep
rm store/* -rf
for i in 0 1 2; do sheep/sheep -d /home/tailai.ly/sheepdog/store/$i -z $i -p 700$i;sleep 1;done
collie/collie cluster format $1
qemu-img create -f raw sheepdog:test 1G
qemu-io -c "write -P 0x1 0 10M" sheepdog:test
qemu-io -c "read -P 0x1 0 10M" sheepdog:test
echo -e "\nBegin tracing\n"
collie/collie debug trace -e
qemu-io -c "write -P 0x1 10M 10M" sheepdog:test
qemu-io -c "read -P 0x1 10M 10M" sheepdog:test
collie/collie debug trace -t
echo -e "\nCat the trace buffer\n"
collie/collie debug trace -C

Thanks,
Yuan

Liu Yuan (13):
      trace: driver trace to work
      trace: low level functions in assembly
      trace: add low level ip2function support
      logger: teach logger funcs to notrace
      sheep: export some structures for trace use
      trace: low-level trace infrastructure proper
      trace: add graph tracer
      trace: add a new interface for trace utility
      trace: add a ring buffer
      sheep: revert coroutine for fixing group_handler() race
      sheep: fix group_handler face
      store, simple: refactor open function
      trace: support cat operation from collie

 collie/Makefile.am   |    6 +
 collie/collie.c      |    6 +
 collie/collie.h      |    1 +
 collie/debug.c       |  142 ++++++++++++++++++++++++
 configure.ac         |   30 +++++-
 include/sheep.h      |   16 +++
 include/util.h       |   26 +++++
 lib/Makefile.am      |    2 +-
 lib/logger.c         |   22 ++--
 lib/ring_buffer.c    |   54 +++++++++
 sheep/Makefile.am    |    6 +-
 sheep/group.c        |   40 +++-----
 sheep/ops.c          |   33 ++++++
 sheep/sheep.c        |    8 ++
 sheep/simple_store.c |  105 ++++++++++--------
 sheep/trace/graph.c  |  109 +++++++++++++++++++
 sheep/trace/mcount.S |   84 ++++++++++++++
 sheep/trace/stabs.c  |  198 ++++++++++++++++++++++++++++++++++
 sheep/trace/trace.c  |  292 ++++++++++++++++++++++++++++++++++++++++++++++++++
 sheep/trace/trace.h  |   71 ++++++++++++
 sheep/trace/trace.ld |   18 +++
 sheep/work.c         |   46 +++-----
 sheep/work.h         |   32 ++++++
 23 files changed, 1230 insertions(+), 117 deletions(-)