def test_add_spent(self):
""" Tests the utxocache:add utxocache:spent tracepoint API
See https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-utxocacheadd
and https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-utxocachespent
"""
self.log.info(
"test the utxocache:add and utxocache:spent tracepoint API")
self.log.info("create an unconfirmed transaction")
self.wallet.send_self_transfer(from_node=self.nodes[0])
# We mine a block to trace changes (add/spent) to the active in-memory cache
# of the UTXO set (see CoinsTip() of CCoinsViewCache). However, in some cases
# temporary clones of the active cache are made. For example, during mining with
# the generate RPC call, the block is first tested in TestBlockValidity(). There,
# a clone of the active cache is modified during a test ConnectBlock() call.
# These are implementation details we don't want to test here. Thus, after
# mining, we invalidate the block, start the tracing, and then trace the cache
# changes to the active utxo cache.
self.log.info("mine and invalidate a block that is later reconsidered")
block_hash = self.generate(self.wallet, 1)[0]
self.nodes[0].invalidateblock(block_hash)
self.log.info(
"hook into the utxocache:add and utxocache:spent tracepoints")
ctx = USDT(pid=self.nodes[0].process.pid)
ctx.enable_probe(probe="utxocache:add", fn_name="trace_utxocache_add")
ctx.enable_probe(probe="utxocache:spent",
fn_name="trace_utxocache_spent")
bpf = BPF(text=utxocache_changes_program, usdt_contexts=[ctx], debug=0)
# The handle_* function is a ctypes callback function called from C. When
# we assert in the handle_* function, the AssertError doesn't propagate
# back to Python. The exception is ignored. We manually count and assert
# that the handle_* functions succeeded.
EXPECTED_HANDLE_ADD_SUCCESS = 2
EXPECTED_HANDLE_SPENT_SUCCESS = 1
handle_add_succeeds = 0
handle_spent_succeeds = 0
expected_utxocache_spents = []
expected_utxocache_adds = []
def handle_utxocache_add(_, data, __):
nonlocal handle_add_succeeds
event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents
self.log.info(f"handle_utxocache_add(): {event}")
add = expected_utxocache_adds.pop(0)
assert_equal(add["txid"], bytes(event.txid[::-1]).hex())
assert_equal(add["index"], event.index)
assert_equal(add["height"], event.height)
assert_equal(add["value"], event.value)
assert_equal(add["is_coinbase"], event.is_coinbase)
handle_add_succeeds += 1
def handle_utxocache_spent(_, data, __):
nonlocal handle_spent_succeeds
event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents
self.log.info(f"handle_utxocache_spent(): {event}")
spent = expected_utxocache_spents.pop(0)
assert_equal(spent["txid"], bytes(event.txid[::-1]).hex())
assert_equal(spent["index"], event.index)
assert_equal(spent["height"], event.height)
assert_equal(spent["value"], event.value)
assert_equal(spent["is_coinbase"], event.is_coinbase)
handle_spent_succeeds += 1
bpf["utxocache_add"].open_perf_buffer(handle_utxocache_add)
bpf["utxocache_spent"].open_perf_buffer(handle_utxocache_spent)
# We trigger a block re-connection. This causes changes (add/spent)
# to the UTXO-cache which in turn triggers the tracepoints.
self.log.info("reconsider the previously invalidated block")
self.nodes[0].reconsiderblock(block_hash)
block = self.nodes[0].getblock(block_hash, 2)
for (block_index, tx) in enumerate(block["tx"]):
for vin in tx["vin"]:
if "coinbase" not in vin:
prevout_tx = self.nodes[0].getrawtransaction(
vin["txid"], True)
prevout_tx_block = self.nodes[0].getblockheader(
prevout_tx["blockhash"])
spends_coinbase = "coinbase" in prevout_tx["vin"][0]
expected_utxocache_spents.append({
"txid":
vin["txid"],
"index":
vin["vout"],
"height":
prevout_tx_block["height"],
"value":
int(prevout_tx["vout"][vin["vout"]]["value"] * COIN),
"is_coinbase":
spends_coinbase,
})
for (i, vout) in enumerate(tx["vout"]):
if vout["scriptPubKey"]["type"] != "nulldata":
expected_utxocache_adds.append({
"txid":
tx["txid"],
"index":
i,
"height":
block["height"],
"value":
int(vout["value"] * COIN),
"is_coinbase":
block_index == 0,
})
assert_equal(EXPECTED_HANDLE_ADD_SUCCESS, len(expected_utxocache_adds))
assert_equal(EXPECTED_HANDLE_SPENT_SUCCESS,
len(expected_utxocache_spents))
bpf.perf_buffer_poll(timeout=200)
bpf.cleanup()
self.log.info(
f"check that we successfully traced {EXPECTED_HANDLE_ADD_SUCCESS} adds and {EXPECTED_HANDLE_SPENT_SUCCESS} spent"
)
assert_equal(0, len(expected_utxocache_adds))
assert_equal(0, len(expected_utxocache_spents))
assert_equal(EXPECTED_HANDLE_ADD_SUCCESS, handle_add_succeeds)
assert_equal(EXPECTED_HANDLE_SPENT_SUCCESS, handle_spent_succeeds)
def load(self):
ctx_name = "ctx"
stack_trace = ""
if self.user_stack:
stack_trace += """
key.user_stack_id = stack_traces.get_stackid(
%s, BPF_F_USER_STACK
);""" % (ctx_name)
else:
stack_trace += "key.user_stack_id = -1;"
if self.kernel_stack:
stack_trace += """
key.kernel_stack_id = stack_traces.get_stackid(
%s, 0
);""" % (ctx_name)
else:
stack_trace += "key.kernel_stack_id = -1;"
trace_count_text = """
int trace_count(void *ctx) {
FILTER
struct key_t key = {};
key.tgid = GET_TGID;
STORE_COMM
%s
counts.increment(key);
return 0;
}
"""
trace_count_text = trace_count_text % (stack_trace)
bpf_text = """
#include <uapi/linux/ptrace.h>
#include <linux/sched.h>
//
struct key_t {
// no pid (thread ID) so that we do not needlessly split this key
u32 tgid;
int kernel_stack_id;
int user_stack_id;
char name[TASK_COMM_LEN];
};
BPF_HASH(counts, struct key_t);
BPF_STACK_TRACE(stack_traces, 1024);
"""
# filter text init
filter_text = []
# We really mean the tgid from the kernel's perspective, which is in
# the top 32 bits of bpf_get_current_pid_tgid().
if self.is_kernel_probe() and self.pid:
# pid filter
filter_text.append(
'u32 pid; pid = bpf_get_current_pid_tgid() >> 32; ' +
'if (pid != %d) { return 0; }' % self.pid)
if self.is_kernel_probe() and self.cpu:
# cpu filter
filter_text.append(
'struct task_struct *task; task = (struct task_struct*)bpf_get_current_task(); '
+ 'if (task->cpu != %d) { return 0; }' % self.cpu)
#
trace_count_text = trace_count_text.replace('FILTER',
'\n '.join(filter_text))
# Do per-pid statistics iff -P is provided
if self.per_pid:
# replace
trace_count_text = trace_count_text.replace(
'GET_TGID', 'bpf_get_current_pid_tgid() >> 32')
trace_count_text = trace_count_text.replace(
'STORE_COMM',
'bpf_get_current_comm(&key.name, sizeof(key.name));')
else:
# skip splitting on PID so these aggregate
# together, and don't store the process name.
trace_count_text = trace_count_text.replace(
'GET_TGID', '0xffffffff')
trace_count_text = trace_count_text.replace('STORE_COMM', '')
self.usdt = None
# usdt
if self.type == "u":
self.usdt = USDT(path=self.library, pid=self.pid)
# iterator all usdt of library above
for probe in self.usdt.enumerate_probes():
if not self.pid and (probe.bin_path != self.library):
continue
# match pattern
if re.match(self.pattern, probe.name):
# This hack is required because the bpf_usdt_readarg
# functions generated need different function names for
# each attached probe. If we just stick to trace_count,
# we'd get multiple bpf_usdt_readarg helpers with the same
# name when enabling more than one USDT probe.
new_func = "trace_count_%d" % self.matched
bpf_text += trace_count_text.replace(
"trace_count", new_func)
self.usdt.enable_probe(probe.name, new_func)
self.matched += 1
if debug:
print(self.usdt.get_text())
else:
bpf_text += trace_count_text
if debug:
print(bpf_text)
# BPF
self.bpf = BPF(text=bpf_text,
usdt_contexts=[self.usdt] if self.usdt else [])
default=1)
parser.add_argument('-d',
type=int,
dest='duration_seconds',
help='Recording duration in seconds',
default=10)
return parser
args = get_arg_parser().parse_args()
print(prog % (next_power_of_two(args.sampling_frequency) - 1))
pid = args.pid
usdt = USDT(path=args.lib_jvm_path, pid=args.pid)
usdt.enable_probe(probe="object__alloc", fn_name="trace_alloc")
bpf = BPF(text=prog % (next_power_of_two(args.sampling_frequency) - 1),
usdt_contexts=[usdt])
time.sleep(float(str(args.duration_seconds)))
if len(bpf["tids"]) == 0:
print("No data found - are DTrace probes enabled in running process?")
stack_traces = bpf["stack_traces"]
all_stacks = []
stack_counts = dict()
for k, v in bpf["counts"].iteritems():
stack = []
def test_attach1(self):
# Enable USDT probe from given PID and verifier generated BPF programs.
u = USDT(pid=int(self.app.pid))
u.enable_probe(probe="probe_point_1", fn_name="do_trace1")
u.enable_probe(probe="probe_point_2", fn_name="do_trace2")
u2 = USDT(pid=int(self.app2.pid))
u2.enable_probe(probe="probe_point_2", fn_name="do_trace2")
u2.enable_probe(probe="probe_point_3", fn_name="do_trace3")
self.bpf_text = self.bpf_text.replace("FILTER",
"pid == %d" % self.app.pid)
b = BPF(text=self.bpf_text, usdt_contexts=[u, u2])
# Event states for each event:
# 0 - probe not caught, 1 - probe caught with correct value,
# 2 - probe caught with incorrect value
self.evt_st_1 = 0
self.evt_st_2 = 0
self.evt_st_3 = 0
self.evt_st_4 = 0
self.evt_st_5 = 0
self.evt_st_6 = 0
def check_event_val(data, event_state, expected_val):
result = ct.cast(data, ct.POINTER(ct.c_int)).contents
if result.value == expected_val:
if (event_state == 0 or event_state == 1):
return 1
return 2
def print_event1(cpu, data, size):
self.evt_st_1 = check_event_val(data, self.evt_st_1, 1)
def print_event2(cpu, data, size):
self.evt_st_2 = check_event_val(data, self.evt_st_2, 2)
def print_event3(cpu, data, size):
self.evt_st_3 = check_event_val(data, self.evt_st_3, 3)
def print_event4(cpu, data, size):
self.evt_st_4 = check_event_val(data, self.evt_st_4, 11)
def print_event5(cpu, data, size):
self.evt_st_5 = check_event_val(data, self.evt_st_5, 12)
def print_event6(cpu, data, size):
self.evt_st_6 = check_event_val(data, self.evt_st_6, 13)
# loop with callback to print_event
b["event1"].open_perf_buffer(print_event1)
b["event2"].open_perf_buffer(print_event2)
b["event3"].open_perf_buffer(print_event3)
b["event4"].open_perf_buffer(print_event4)
b["event5"].open_perf_buffer(print_event5)
b["event6"].open_perf_buffer(print_event6)
# three iterations to make sure we get some probes and have time to process them
for i in range(5):
b.perf_buffer_poll()
# note that event1 and event4 do not really fire, so their state should be 0
# use separate asserts so that if test fails we know which one is the culprit
self.assertTrue(self.evt_st_1 == 1)
self.assertTrue(self.evt_st_2 == 1)
self.assertTrue(self.evt_st_3 == 0)
self.assertTrue(self.evt_st_4 == 0)
self.assertTrue(self.evt_st_5 == 1)
self.assertTrue(self.evt_st_6 == 1)
info->num_calls += 1;
info->total_ns += bpf_ktime_get_ns() - e->timestamp;
sysentry.delete(&pid);
return 0;
}
#endif // LATENCY
#endif // SYSCALLS
""".replace("READ_CLASS", read_class) \
.replace("READ_METHOD", read_method) \
.replace("PID_FILTER", "if ((pid >> 32) != %d) { return 0; }" % args.pid) \
.replace("DEFINE_NOLANG", "#define NOLANG" if not language else "") \
.replace("DEFINE_LATENCY", "#define LATENCY" if args.latency else "") \
.replace("DEFINE_SYSCALLS", "#define SYSCALLS" if args.syscalls else "")
if language:
usdt = USDT(pid=args.pid)
usdt.enable_probe_or_bail(entry_probe, "trace_entry")
if args.latency:
usdt.enable_probe_or_bail(return_probe, "trace_return")
else:
usdt = None
if args.verbose:
if usdt:
print(usdt.get_text())
print(program)
bpf = BPF(text=program, usdt_contexts=[usdt] if usdt else [])
if args.syscalls:
syscall_regex = "^[Ss]y[Ss]_.*"
bpf.attach_kprobe(event_re=syscall_regex, fn_name="syscall_entry")
help='pid of process emitting probes')
args = parser.parse_args()
bpfs = dict()
# These probes do not currently exist on any branch, and were used solely for my own testing.
# You can use any probes that pass through a BSONObj size and a BSONObj char* in that order.
probes = []#["query1", "query", "query1", "query1R", "queryR", "query2", "query3"]
# necessary to have multiple bpfs, one for each object,
# due to restriction on number of insns per bpf object.
# copying out long strings requires a large number of insns,
# and duplicating that for each entrypt function is prohibitively
# large in terms of number of isns.
for probe in probes:
print(probe)
usdt = USDT(pid=args.pid[0])
usdt.enable_probe(probe, fn_name="str_entry_{}".format(probe))
bpfs[probe] = BPF(text=code.replace("#PROBE#", probe), usdt_contexts=[usdt])
print(code)
wrks = []
for probe in probes:
print(probe)
bpf = bpfs[probe]
bpf["str_out_{}".format(probe)].open_perf_buffer(gen_callback(probe, bpfs))
wrks.append(WorkerThread(gen_work(probe, bpfs)))
master = WorkerMaster(wrks)
master.start_all()
print("Ready")
int endQueryOp(struct pt_regs *ctx) {
struct endQueryOutput out = {};
void* summaryPtr = NULL;
out.opCtx = NULL;
bpf_usdt_readarg(1, ctx, &out.opCtx);
if(!out.opCtx) return 0;
bpf_usdt_readarg(2, ctx, &summaryPtr);
if(!summaryPtr) return 0;
bpf_probe_read(&out.summaryStats, sizeof(out.summaryStats), summaryPtr);
bpf_usdt_readarg(3, ctx, &out.numResults);
endQuery.perf_submit(ctx, &out, sizeof(out));
return 0;
}
"""
probe = USDT(int(sys.argv[1]))
probe.enable_probe(probe="findCmdPlan", fn_name="findCmdPlan")
toAgg = USDT(int(sys.argv[1]))
toAgg.enable_probe(probe="findToAgg", fn_name="findCmdToAgg")
# beginQuery = USDT(int(sys.argv[1]))
probe.enable_probe(probe="beginQueryOp", fn_name="beginQueryOp")
probe.enable_probe(probe="endQueryOp", fn_name="endQueryOp")
class BeginQuery(ct.Structure):
_fields_ = [("nss", ct.c_char * 50), ("bson", ct.c_byte * 100),
("queryObjSz", ct.c_uint), ("nreturn", ct.c_longlong),
("nskip", ct.c_longlong)]
#!/usr/bin/env python3
from bcc import BPF, USDT
import sys
bpf_source = """
#include <uapi/linux/ptrace.h>
int trace_binary_exec(struct pt_regs *ctx) {
u64 pid = bpf_get_current_pid_tgid();
bpf_trace_printk("New process running with PID %d\\n", pid);
return 0;
}
"""
usdt_ctx = USDT(pid=int(sys.argv[1]))
usdt_ctx.enable_probe(probe="probe-main", fn_name="trace_binary_exec")
bpf = BPF(text=bpf_source, usdt_contexts=[usdt_ctx], debug=4)
bpf.trace_print()
def enable_usdt_probe(self, probe_name, fn_name):
if not self.usdt_ctx:
self.usdt_ctx = USDT(pid=self.args.pid)
self.usdt_ctx.enable_probe(probe_name, fn_name)
from bcc import BPF, USDT
bpf_source = """
#include<uapi/linux/ptrace.h>
int trace_binary_exec(struct pt_regs *ctx) {
u64 pid = bpf_get_current_pid_tgid();
bpf_trace_printk("New hello-bpf process running with PID: %d\n", pid);
}
"""
usdt = USDT(path="./test")
usdt.enable_probe(probe="probe-main", fn_name="trace_binary_exec")
bpf = BPF(text= bpf_source, usdt_contexts= usdt)
bpf.trace_print()
def display_stats(commands, update_interval):
previous_stats = {}
while True:
stats = commands.items()
# :shrug:
if stats.__str__() != previous_stats.__str__():
commands.print_log2_hist("command strlen")
time.sleep(update_interval)
previous_stats = stats
if __name__ == '__main__':
if len(sys.argv) < 2:
print("usage: ... <memcached_pid> [<update_interval>]")
sys.exit(1)
memcached_pid = int(sys.argv[1])
update_interval = float(sys.argv[2]) if len(sys.argv) >= 3 else 0.1
u = USDT(pid=int(sys.argv[1]))
u.enable_probe(probe='process__command__start', fn_name='command_start')
b = BPF(text=bpf_text, usdt_contexts=[u])
print('Waiting for commands...')
display_stats(b.get_table('command_dist'), update_interval)
def run_test(self):
# Tests the validation:block_connected tracepoint by generating blocks
# and comparing the values passed in the tracepoint arguments with the
# blocks.
# See https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-validationblock_connected
class Block(ctypes.Structure):
_fields_ = [
("hash", ctypes.c_ubyte * 32),
("height", ctypes.c_int),
("transactions", ctypes.c_int64),
("inputs", ctypes.c_int),
("sigops", ctypes.c_int64),
("duration", ctypes.c_uint64),
]
def __repr__(self):
return "ConnectedBlock(hash=%s height=%d, transactions=%d, inputs=%d, sigops=%d, duration=%d)" % (
bytes(self.hash[::-1]).hex(), self.height,
self.transactions, self.inputs, self.sigops, self.duration)
# The handle_* function is a ctypes callback function called from C. When
# we assert in the handle_* function, the AssertError doesn't propagate
# back to Python. The exception is ignored. We manually count and assert
# that the handle_* functions succeeded.
BLOCKS_EXPECTED = 2
blocks_checked = 0
expected_blocks = list()
self.log.info("hook into the validation:block_connected tracepoint")
ctx = USDT(path=str(self.options.bitcoind))
ctx.enable_probe(probe="validation:block_connected",
fn_name="trace_block_connected")
bpf = BPF(text=validation_blockconnected_program,
usdt_contexts=[ctx],
debug=0)
def handle_blockconnected(_, data, __):
nonlocal expected_blocks, blocks_checked
event = ctypes.cast(data, ctypes.POINTER(Block)).contents
self.log.info(f"handle_blockconnected(): {event}")
block = expected_blocks.pop(0)
assert_equal(block["hash"], bytes(event.hash[::-1]).hex())
assert_equal(block["height"], event.height)
assert_equal(len(block["tx"]), event.transactions)
assert_equal(len([tx["vin"] for tx in block["tx"]]), event.inputs)
assert_equal(0, event.sigops) # no sigops in coinbase tx
# only plausibility checks
assert (event.duration > 0)
blocks_checked += 1
bpf["block_connected"].open_perf_buffer(handle_blockconnected)
self.log.info(f"mine {BLOCKS_EXPECTED} blocks")
block_hashes = self.generatetoaddress(self.nodes[0], BLOCKS_EXPECTED,
ADDRESS_BCRT1_UNSPENDABLE)
for block_hash in block_hashes:
expected_blocks.append(self.nodes[0].getblock(block_hash, 2))
bpf.perf_buffer_poll(timeout=200)
bpf.cleanup()
self.log.info(f"check that we traced {BLOCKS_EXPECTED} blocks")
assert_equal(BLOCKS_EXPECTED, blocks_checked)
assert_equal(0, len(expected_blocks))
switch(type) {
case READ_CMD:
read_out.increment(delta);
break;
case WRITE_CMD:
write_out.increment(delta);
break;
default:
break;
}
}
return 0;
}
"""
command_start = USDT(pid=pid)
command_start.enable_probe(probe="commandStart", fn_name="command_start")
command_end = USDT(pid=pid)
command_end.enable_probe(probe="commandEnd", fn_name="command_end")
b = BPF(text=text, usdt_contexts=[command_start, command_end])
def main():
try:
print("Read time histogram:")
b["read_out"].print_linear_hist("Elapsed time in ms")
print("Write time histogram:")
b["write_out"].print_linear_hist("Elapsed time in ms")
except KeyboardInterrupt:
exit()
def test_flush(self):
""" Tests the utxocache:flush tracepoint API.
See https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-utxocacheflush"""
self.log.info("test the utxocache:flush tracepoint API")
self.log.info("hook into the utxocache:flush tracepoint")
ctx = USDT(pid=self.nodes[0].process.pid)
ctx.enable_probe(probe="utxocache:flush",
fn_name="trace_utxocache_flush")
bpf = BPF(text=utxocache_flushes_program, usdt_contexts=[ctx], debug=0)
# The handle_* function is a ctypes callback function called from C. When
# we assert in the handle_* function, the AssertError doesn't propagate
# back to Python. The exception is ignored. We manually count and assert
# that the handle_* functions succeeded.
EXPECTED_HANDLE_FLUSH_SUCCESS = 3
handle_flush_succeeds = 0
expected_flushes = list()
def handle_utxocache_flush(_, data, __):
nonlocal handle_flush_succeeds
event = ctypes.cast(data, ctypes.POINTER(UTXOCacheFlush)).contents
self.log.info(f"handle_utxocache_flush(): {event}")
expected_flushes.remove({
"mode": FLUSHMODE_NAME[event.mode],
"for_prune": event.for_prune,
"size": event.size
})
# sanity checks only
assert (event.memory > 0)
assert (event.duration > 0)
handle_flush_succeeds += 1
bpf["utxocache_flush"].open_perf_buffer(handle_utxocache_flush)
self.log.info("stop the node to flush the UTXO cache")
UTXOS_IN_CACHE = 2 # might need to be changed if the eariler tests are modified
# A node shutdown causes two flushes. One that flushes UTXOS_IN_CACHE
# UTXOs and one that flushes 0 UTXOs. Normally the 0-UTXO-flush is the
# second flush, however it can happen that the order changes.
expected_flushes.append({
"mode": "ALWAYS",
"for_prune": False,
"size": UTXOS_IN_CACHE
})
expected_flushes.append({
"mode": "ALWAYS",
"for_prune": False,
"size": 0
})
self.stop_node(0)
bpf.perf_buffer_poll(timeout=200)
bpf.cleanup()
self.log.info("check that we don't expect additional flushes")
assert_equal(0, len(expected_flushes))
self.log.info("restart the node with -prune")
self.start_node(0, ["-fastprune=1", "-prune=1"])
BLOCKS_TO_MINE = 350
self.log.info(f"mine {BLOCKS_TO_MINE} blocks to be able to prune")
self.generate(self.wallet, BLOCKS_TO_MINE)
self.log.info("test the utxocache:flush tracepoint API with pruning")
self.log.info("hook into the utxocache:flush tracepoint")
ctx = USDT(pid=self.nodes[0].process.pid)
ctx.enable_probe(probe="utxocache:flush",
fn_name="trace_utxocache_flush")
bpf = BPF(text=utxocache_flushes_program, usdt_contexts=[ctx], debug=0)
bpf["utxocache_flush"].open_perf_buffer(handle_utxocache_flush)
self.log.info(f"prune blockchain to trigger a flush for pruning")
expected_flushes.append({"mode": "NONE", "for_prune": True, "size": 0})
self.nodes[0].pruneblockchain(315)
bpf.perf_buffer_poll(timeout=500)
bpf.cleanup()
self.log.info(
f"check that we don't expect additional flushes and that the handle_* function succeeded"
)
assert_equal(0, len(expected_flushes))
assert_equal(EXPECTED_HANDLE_FLUSH_SUCCESS, handle_flush_succeeds)
def _find_usdt_probe(self):
self.usdt = USDT(path=self.library, pid=Probe.pid)
for probe in self.usdt.enumerate_probes():
if probe.name == self.usdt_name:
return # Found it, will enable later
self._bail("unrecognized USDT probe %s" % self.usdt_name)
if (delta >= """ + str(min_ns) + """) {
// populate and emit data struct
struct data_t data = {.pid = pid, .ts = sp->ts, .delta = delta};
bpf_probe_read(&data.query, sizeof(data.query), (void *)sp->query);
events.perf_submit(ctx, &data, sizeof(data));
}
start_tmp.delete(&pid);
return 0;
};
"""
# enable USDT probe from given PID
u = USDT(pid=pid)
u.enable_probe(probe="query__start", fn_name="do_start")
u.enable_probe(probe="query__done", fn_name="do_done")
if debug:
print(u.get_text())
print(bpf_text)
# initialize BPF
b = BPF(text=bpf_text, usdt_contexts=[u])
# header
print("Tracing MySQL server queries for PID %d slower than %s ms..." %
(pid, min_ms_text))
print("%-14s %-6s %8s %s" % ("TIME(s)", "PID", "MS", "QUERY"))
return 0;
}
"""
bpf_text = bpf_text.replace("MAX_SAMPLE_SIZE", str(this_maxsamplesize))
bpf_text = bpf_text.replace("FILTER_STRING", this_filter)
if this_filter:
bpf_text = bpf_text.replace(
"FILTER_STATEMENT", "if (!filter(start_data.input)) { return 0; }")
else:
bpf_text = bpf_text.replace("FILTER_STATEMENT", "")
# Create USDT context
print("lat_avg.py - Attaching probes to pid: %d; filter: %s" %
(this_pid, this_filter))
usdt_ctx = USDT(pid=this_pid)
if args.sdt:
usdt_ctx.enable_probe(probe="usdt_sample_lib1_sdt:operation_start_sdt",
fn_name="trace_operation_start")
usdt_ctx.enable_probe(probe="usdt_sample_lib1_sdt:operation_end_sdt",
fn_name="trace_operation_end")
else:
usdt_ctx.enable_probe(probe="usdt_sample_lib1:operation_start",
fn_name="trace_operation_start")
usdt_ctx.enable_probe(probe="usdt_sample_lib1:operation_end",
fn_name="trace_operation_end")
# Create BPF context, load BPF program
bpf_ctx = BPF(text=bpf_text, usdt_contexts=[usdt_ctx], debug=debugLevel)
from bcc import BPF, USDT
bpf_source = """
#include <uapi/linux/ptrace.h>
int trace_binary_exec(struct pt_regs *ctx) {
u64 pid = bpf_get_current_pid_tgid();
bpf_trace_printk("New hello_usdt process running with PID: %d", pid);
}
"""
usdt = USDT(path="./ha")
usdt.enable_probe(probe='probe-main', fn_name="trace_binary_exec")
bpf = BPF(text=bpf_source, usdt=usdt)
bpf.trace_print()
uint64_t addr;
char query[128];
/*
* Read the first argument from the query-start probe, which is the query.
* The format of this probe is:
* query-start(query, connectionid, database, user, host)
* see: https://dev.mysql.com/doc/refman/5.7/en/dba-dtrace-ref-query.html
*/
bpf_usdt_readarg(1, ctx, &addr);
bpf_trace_printk("%s\\n", addr);
return 0;
};
"""
# enable USDT probe from given PID
u = USDT(pid=int(pid))
u.enable_probe(probe="query__start", fn_name="do_trace")
if debug:
print(u.get_text())
print(bpf_text)
# initialize BPF
b = BPF(text=bpf_text, usdt_contexts=[u])
# header
print("%-18s %-16s %-6s %s" % ("TIME(s)", "COMM", "PID", "QUERY"))
# format output
while 1:
try:
(task, pid, cpu, flags, ts, msg) = b.trace_fields()
def load(self):
ctx_name = "ctx"
stack_trace = ""
if self.user_stack:
stack_trace += """
key.user_stack_id = stack_traces.get_stackid(
%s, BPF_F_REUSE_STACKID | BPF_F_USER_STACK
);""" % (ctx_name)
else:
stack_trace += "key.user_stack_id = -1;"
if self.kernel_stack:
stack_trace += """
key.kernel_stack_id = stack_traces.get_stackid(
%s, BPF_F_REUSE_STACKID
);""" % (ctx_name)
else:
stack_trace += "key.kernel_stack_id = -1;"
trace_count_text = """
int trace_count(void *ctx) {
FILTER
struct key_t key = {};
key.tgid = GET_TGID;
STORE_COMM
%s
u64 zero = 0;
u64 *val = counts.lookup_or_init(&key, &zero);
(*val)++;
return 0;
}
"""
trace_count_text = trace_count_text % (stack_trace)
bpf_text = """#include <uapi/linux/ptrace.h>
#include <linux/sched.h>
struct key_t {
// no pid (thread ID) so that we do not needlessly split this key
u32 tgid;
int kernel_stack_id;
int user_stack_id;
char name[TASK_COMM_LEN];
};
BPF_HASH(counts, struct key_t);
BPF_STACK_TRACE(stack_traces, 1024);
"""
# We really mean the tgid from the kernel's perspective, which is in
# the top 32 bits of bpf_get_current_pid_tgid().
if self.is_kernel_probe() and self.pid:
trace_count_text = trace_count_text.replace(
'FILTER',
('u32 pid; pid = bpf_get_current_pid_tgid() >> 32; ' +
'if (pid != %d) { return 0; }') % (self.pid))
else:
trace_count_text = trace_count_text.replace('FILTER', '')
# We need per-pid statistics when tracing a user-space process, because
# the meaning of the symbols depends on the pid. We also need them if
# per-pid statistics were requested with -P, or for user stacks.
if self.per_pid or not self.is_kernel_probe() or self.user_stack:
trace_count_text = trace_count_text.replace(
'GET_TGID', 'bpf_get_current_pid_tgid() >> 32')
trace_count_text = trace_count_text.replace(
'STORE_COMM',
'bpf_get_current_comm(&key.name, sizeof(key.name));')
else:
# kernel stacks only. skip splitting on PID so these aggregate
# together, and don't store the process name.
trace_count_text = trace_count_text.replace(
'GET_TGID', '0xffffffff')
trace_count_text = trace_count_text.replace('STORE_COMM', '')
self.usdt = None
if self.type == "u":
self.usdt = USDT(path=self.library, pid=self.pid)
for probe in self.usdt.enumerate_probes():
if not self.pid and (probe.bin_path != self.library):
continue
if re.match(self.pattern, probe.name):
# This hack is required because the bpf_usdt_readarg
# functions generated need different function names for
# each attached probe. If we just stick to trace_count,
# we'd get multiple bpf_usdt_readarg helpers with the same
# name when enabling more than one USDT probe.
new_func = "trace_count_%d" % self.matched
bpf_text += trace_count_text.replace(
"trace_count", new_func)
self.usdt.enable_probe(probe.name, new_func)
self.matched += 1
if debug:
print(self.usdt.get_text())
else:
bpf_text += trace_count_text
if debug:
print(bpf_text)
self.bpf = BPF(text=bpf_text,
usdt_contexts=[self.usdt] if self.usdt else [])
u64 delta = bpf_ktime_get_ns() - tempp->timestamp;
if (delta >= """ + str(threshold_ns) + """) {
struct data_t data = {};
data.pid = pid >> 32; // only process id
data.timestamp = tempp->timestamp;
data.duration = delta;
bpf_probe_read(&data.query, sizeof(data.query), tempp->query);
events.perf_submit(ctx, &data, sizeof(data));
}
temp.delete(&pid);
return 0;
}
"""
usdts = map(lambda pid: USDT(pid=pid), args.pids)
for usdt in usdts:
usdt.enable_probe("query__start", "probe_start")
usdt.enable_probe("query__done", "probe_end")
bpf = BPF(text=program, usdt_contexts=usdts)
if args.verbose:
print('\n'.join(map(lambda u: u.get_text(), usdts)))
print(program)
class Data(ct.Structure):
_fields_ = [("pid", ct.c_ulonglong), ("timestamp", ct.c_ulonglong),
("delta", ct.c_ulonglong), ("query", ct.c_char * 256)]
def load(self):
ctx_name = "ctx"
stack_trace = ""
if self.user_stack:
stack_trace += """
key.user_stack_id = stack_traces.get_stackid(
%s, BPF_F_USER_STACK
);""" % (ctx_name)
else:
stack_trace += "key.user_stack_id = -1;"
if self.kernel_stack:
stack_trace += """
key.kernel_stack_id = stack_traces.get_stackid(
%s, 0
);""" % (ctx_name)
else:
stack_trace += "key.kernel_stack_id = -1;"
trace_count_text = """
int trace_count(void *ctx) {
FILTER
struct key_t key = {};
key.tgid = GET_TGID;
STORE_COMM
%s
counts.increment(key);
return 0;
}
"""
trace_count_text = trace_count_text % (stack_trace)
bpf_text = """#include <uapi/linux/ptrace.h>
#include <linux/sched.h>
struct key_t {
// no pid (thread ID) so that we do not needlessly split this key
u32 tgid;
int kernel_stack_id;
int user_stack_id;
char name[TASK_COMM_LEN];
};
BPF_HASH(counts, struct key_t);
BPF_STACK_TRACE(stack_traces, 1024);
"""
filter_text = []
trace_count_text = trace_count_text.replace('FILTER',
'\n '.join(filter_text))
# Do per-pid statistics iff -P is provided
if self.per_pid:
trace_count_text = trace_count_text.replace(
'GET_TGID', 'bpf_get_current_pid_tgid() >> 32')
trace_count_text = trace_count_text.replace(
'STORE_COMM',
'bpf_get_current_comm(&key.name, sizeof(key.name));')
else:
# skip splitting on PID so these aggregate
# together, and don't store the process name.
trace_count_text = trace_count_text.replace(
'GET_TGID', '0xffffffff')
trace_count_text = trace_count_text.replace('STORE_COMM', '')
if self.type == "u":
self.usdt = USDT(path=self.library, pid=self.pid)
for probe in self.usdt.enumerate_probes():
if not self.pid and (str(probe.bin_path, 'ascii') !=
self.library):
continue
parts = self.pattern.split(":")
if len(parts) == 1:
provider_name = None
usdt_name = parts[0].encode("ascii")
else:
provider_name = parts[0]
usdt_name = parts[1]
if (str(probe.name, 'ascii') == usdt_name
and str(probe.provider, 'ascii') == provider_name):
# This hack is required because the bpf_usdt_readarg
# functions generated need different function names for
# each attached probe. If we just stick to trace_count,
# we'd get multiple bpf_usdt_readarg helpers with the same
# name when enabling more than one USDT probe.
new_func = "trace_count_%d" % self.matched
bpf_text += trace_count_text.replace(
"trace_count", new_func)
self.usdt.enable_probe(str(probe.name, 'ascii'), new_func)
self.matched += 1
if DEBUG:
print(self.usdt.get_text())
else:
bpf_text += trace_count_text
if DEBUG:
print(bpf_text)
self.bpf = BPF(text=bpf_text,
usdt_contexts=[self.usdt] if self.usdt else [])
timestampp = temp.lookup(&pid);
if (!timestampp)
return 0;
u64 delta = bpf_ktime_get_ns() - *timestampp;
if (delta/1000000 < %d)
return 0;
delta /= %d;
latency.increment(bpf_log2l(delta));
temp.delete(&pid);
return 0;
}
""" % (args.threshold, 1000000 if args.milliseconds else 1000)
usdt = USDT(pid=int(dbpid))
usdt.enable_probe("query__start", "probe_start")
usdt.enable_probe("query__done", "probe_end")
bpf = BPF(text=program, usdt_contexts=[usdt])
if args.verbose:
print(usdt.get_text())
print(program)
print(
"Tracing database queries slower than %dms for PID %d... Ctrl+C to quit." %
(args.threshold, dbpid))
try:
sleep(999999999999)
except KeyboardInterrupt:
bpf = BPF(text=program)
bpf.attach_uprobe(name=args.path, sym=mysql_func_name,
fn_name="query_start")
bpf.attach_uretprobe(name=args.path, sym=mysql_func_name,
fn_name="query_end")
else:
# USDT mode
if not args.pids or len(args.pids) == 0:
if args.db == "mysql":
args.pids = map(int, subprocess.check_output(
"pidof mysqld".split()).split())
elif args.db == "postgres":
args.pids = map(int, subprocess.check_output(
"pidof postgres".split()).split())
usdts = list(map(lambda pid: USDT(pid=pid), args.pids))
for usdt in usdts:
usdt.enable_probe("query__start", "query_start")
usdt.enable_probe("query__done", "query_end")
if args.verbose:
print('\n'.join(map(lambda u: u.get_text(), usdts)))
bpf = BPF(text=program, usdt_contexts=usdts)
if args.verbose or args.ebpf:
print(program)
if args.ebpf:
exit()
start = BPF.monotonic_time()
def test_attach1(self):
# enable USDT probe from given PID and verifier generated BPF programs
u = USDT(pid=int(self.app.pid))
u.enable_probe(probe="probe_point_1", fn_name="do_trace1")
u.enable_probe(probe="probe_point_2", fn_name="do_trace2")
u.enable_probe(probe="probe_point_3", fn_name="do_trace3")
u.enable_probe(probe="probe_point_4", fn_name="do_trace4")
u.enable_probe(probe="probe_point_5", fn_name="do_trace5")
b = BPF(text=self.bpf_text, usdt_contexts=[u], debug=4)
# Event states for each event:
# 0 - probe not caught, 1 - probe caught with correct value,
# 2 - probe caught with incorrect value
self.evt_st_1 = 0
self.evt_st_2 = 0
self.evt_st_3 = 0
# define output data structure in Python
class Data1(ct.Structure):
_fields_ = [("v1", ct.c_char), ("v2", ct.c_int)]
class Data2(ct.Structure):
_fields_ = [("v1", ct.c_int), ("v2", ct.c_char)]
class Data3(ct.Structure):
_fields_ = [("v1", ct.c_int), ("v2", ct.c_int)]
class Data4(ct.Structure):
_fields_ = [("v1", ct.c_ulonglong), ("v2", ct.c_char * 64)]
class Data5(ct.Structure):
_fields_ = [("v1", ct.c_char * 64), ("v2", ct.c_ulonglong)]
def check_event_val(event, event_state, v1, v2, v3, v4):
if ((event.v1 == v1 and event.v2 == v2)
or (event.v1 == v3 and event.v2 == v4)):
if (event_state == 0 or event_state == 1):
return 1
return 2
def print_event1(cpu, data, size):
event = ct.cast(data, ct.POINTER(Data1)).contents
self.evt_st_1 = check_event_val(event, self.evt_st_1, b'\x0d', 40,
b'\x08', 200)
def print_event2(cpu, data, size):
event = ct.cast(data, ct.POINTER(Data2)).contents
# pretend we have two identical probe points to simplify the code
self.evt_st_2 = check_event_val(event, self.evt_st_2, 5, b'\x04',
5, b'\x04')
def print_event3(cpu, data, size):
event = ct.cast(data, ct.POINTER(Data3)).contents
self.evt_st_3 = check_event_val(event, self.evt_st_3, 200, 40, 8,
13)
def print_event4(cpu, data, size):
event = ct.cast(data, ct.POINTER(Data4)).contents
print("%s" % event.v2)
def print_event5(cpu, data, size):
event = ct.cast(data, ct.POINTER(Data5)).contents
print("%s" % event.v1)
# loop with callback to print_event
b["event1"].open_perf_buffer(print_event1)
b["event2"].open_perf_buffer(print_event2)
b["event3"].open_perf_buffer(print_event3)
b["event4"].open_perf_buffer(print_event4)
b["event5"].open_perf_buffer(print_event5)
# three iterations to make sure we get some probes and have time to process them
for i in range(3):
b.perf_buffer_poll()
self.assertTrue(self.evt_st_1 == 1 and self.evt_st_2 == 1
and self.evt_st_3 == 1)
def run_test(self):
# Tests the net:inbound_message and net:outbound_message tracepoints
# See https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#context-net
class P2PMessage(ctypes.Structure):
_fields_ = [
("peer_id", ctypes.c_uint64),
("peer_addr", ctypes.c_char * MAX_PEER_ADDR_LENGTH),
("peer_conn_type", ctypes.c_char * MAX_PEER_CONN_TYPE_LENGTH),
("msg_type", ctypes.c_char * MAX_MSG_TYPE_LENGTH),
("msg_size", ctypes.c_uint64),
("msg", ctypes.c_ubyte * MAX_MSG_DATA_LENGTH),
]
def __repr__(self):
return f"P2PMessage(peer={self.peer_id}, addr={self.peer_addr.decode('utf-8')}, conn_type={self.peer_conn_type.decode('utf-8')}, msg_type={self.msg_type.decode('utf-8')}, msg_size={self.msg_size})"
self.log.info(
"hook into the net:inbound_message and net:outbound_message tracepoints"
)
ctx = USDT(path=str(self.options.bitcoind))
ctx.enable_probe(probe="net:inbound_message",
fn_name="trace_inbound_message")
ctx.enable_probe(probe="net:outbound_message",
fn_name="trace_outbound_message")
bpf = BPF(text=net_tracepoints_program, usdt_contexts=[ctx], debug=0)
# The handle_* function is a ctypes callback function called from C. When
# we assert in the handle_* function, the AssertError doesn't propagate
# back to Python. The exception is ignored. We manually count and assert
# that the handle_* functions succeeded.
EXPECTED_INOUTBOUND_VERSION_MSG = 1
checked_inbound_version_msg = 0
checked_outbound_version_msg = 0
def check_p2p_message(event, inbound):
nonlocal checked_inbound_version_msg, checked_outbound_version_msg
if event.msg_type.decode("utf-8") == "version":
self.log.info(
f"check_p2p_message(): {'inbound' if inbound else 'outbound'} {event}"
)
peer = self.nodes[0].getpeerinfo()[0]
msg = msg_version()
msg.deserialize(BytesIO(bytes(event.msg[:event.msg_size])))
assert_equal(peer["id"], event.peer_id, peer["id"])
assert_equal(peer["addr"], event.peer_addr.decode("utf-8"))
assert_equal(peer["connection_type"],
event.peer_conn_type.decode("utf-8"))
if inbound:
checked_inbound_version_msg += 1
else:
checked_outbound_version_msg += 1
def handle_inbound(_, data, __):
event = ctypes.cast(data, ctypes.POINTER(P2PMessage)).contents
check_p2p_message(event, True)
def handle_outbound(_, data, __):
event = ctypes.cast(data, ctypes.POINTER(P2PMessage)).contents
check_p2p_message(event, False)
bpf["inbound_messages"].open_perf_buffer(handle_inbound)
bpf["outbound_messages"].open_perf_buffer(handle_outbound)
self.log.info("connect a P2P test node to our bitcoind node")
test_node = P2PInterface()
self.nodes[0].add_p2p_connection(test_node)
bpf.perf_buffer_poll(timeout=200)
self.log.info(
"check that we got both an inbound and outbound version message")
assert_equal(EXPECTED_INOUTBOUND_VERSION_MSG,
checked_inbound_version_msg)
assert_equal(EXPECTED_INOUTBOUND_VERSION_MSG,
checked_outbound_version_msg)
bpf.cleanup()
"-DHHVM_TRACING_MAX_STACK_FRAMES={}".format(200),
"-DHHVM_TRACING_FILE_NAME_MAX={}".format(128),
"-DHHVM_TRACING_CLASS_NAME_MAX={}".format(128),
"-DHHVM_TRACING_FUNCTION_MAX={}".format(128),
]
bpf_text = ""
with open("../strobelight_hhvm_structs.h", "r") as structs_file:
bpf_text += structs_file.read() + "\n"
with open("./strobelight_hhvm_signal_latency.c", "r") as latency_file:
bpf_text += latency_file.read()
usdts = []
for pid in args.pids:
usdt = USDT(pid=pid)
usdt.enable_probe("hhvm_surprise", "on_hhvm_signal_handler")
print("Enabled tracing on {}\n".format(pid))
usdts.append(usdt)
bpf = BPF(text=bpf_text,
usdt_contexts=usdts,
cflags=cflags)
hhvm_pids = bpf.get_table("hhvm_pids")
for pid in args.pids:
hhvm_pids[c_int(pid)] = c_int(1)
# A generic perf event for driving the signal
bpf.attach_perf_event(
ev_type=PerfType.HARDWARE,
import os
from bcc import USDT
import ctypes as ct
from ctypes.util import find_library
from typing import get_type_hints, List, Any
from ebph import defs
from ebph.logger import get_logger
logger = get_logger()
libebph = ct.CDLL(defs.LIBEBPH, use_errno=True)
usdt_context = USDT(pid=os.getpid())
def command(func):
"""
A decorator that allows a function to provide an interface into a libebph
command of the same name. Types are determined using Python type hints.
"""
name = func.__name__
th = get_type_hints(func)
argtypes = [v for k, v in th.items() if k != 'return']
try:
restype = th['return']
except KeyError:
restype = None
@staticmethod
def wrapper(*args, **kwargs):
def _enable_usdt_probe(self):
self.usdt_ctx = USDT(path=self.library, pid=self.pid)
self.usdt_ctx.enable_probe(
self.function, self.probe_func_name)
def test_uncache(self):
""" Tests the utxocache:uncache tracepoint API.
https://github.com/bitcoin/bitcoin/blob/master/doc/tracing.md#tracepoint-utxocacheuncache
"""
# To trigger an UTXO uncache from the cache, we create an invalid transaction
# spending a not-cached, but existing UTXO. During transaction validation, this
# the UTXO is added to the utxo cache, but as the transaction is invalid, it's
# uncached again.
self.log.info("testing the utxocache:uncache tracepoint API")
# Retrieve the txid for the UTXO created in the first block. This UTXO is not
# in our UTXO cache.
EARLY_BLOCK_HEIGHT = 1
block_1_hash = self.nodes[0].getblockhash(EARLY_BLOCK_HEIGHT)
block_1 = self.nodes[0].getblock(block_1_hash)
block_1_coinbase_txid = block_1["tx"][0]
# Create a transaction and invalidate it by changing the txid of the previous
# output to the coinbase txid of the block at height 1.
invalid_tx = self.wallet.create_self_transfer()["tx"]
invalid_tx.vin[0].prevout.hash = int(block_1_coinbase_txid, 16)
self.log.info("hooking into the utxocache:uncache tracepoint")
ctx = USDT(pid=self.nodes[0].process.pid)
ctx.enable_probe(probe="utxocache:uncache",
fn_name="trace_utxocache_uncache")
bpf = BPF(text=utxocache_changes_program, usdt_contexts=[ctx], debug=0)
# The handle_* function is a ctypes callback function called from C. When
# we assert in the handle_* function, the AssertError doesn't propagate
# back to Python. The exception is ignored. We manually count and assert
# that the handle_* functions succeeded.
EXPECTED_HANDLE_UNCACHE_SUCCESS = 1
handle_uncache_succeeds = 0
def handle_utxocache_uncache(_, data, __):
nonlocal handle_uncache_succeeds
event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents
self.log.info(f"handle_utxocache_uncache(): {event}")
assert_equal(block_1_coinbase_txid, bytes(event.txid[::-1]).hex())
assert_equal(0, event.index) # prevout index
assert_equal(EARLY_BLOCK_HEIGHT, event.height)
assert_equal(50 * COIN, event.value)
assert_equal(True, event.is_coinbase)
handle_uncache_succeeds += 1
bpf["utxocache_uncache"].open_perf_buffer(handle_utxocache_uncache)
self.log.info(
"testmempoolaccept the invalid transaction to trigger an UTXO-cache uncache"
)
result = self.nodes[0].testmempoolaccept(
[invalid_tx.serialize().hex()])[0]
assert_equal(result["allowed"], False)
bpf.perf_buffer_poll(timeout=100)
bpf.cleanup()
self.log.info(
f"check that we successfully traced {EXPECTED_HANDLE_UNCACHE_SUCCESS} uncaches"
)
assert_equal(EXPECTED_HANDLE_UNCACHE_SUCCESS, handle_uncache_succeeds)
