From 01133ccb0ee31f7108f7cb4e89454f2693df912e Mon Sep 17 00:00:00 2001 From: guanglei Date: Thu, 1 Jun 2006 05:46:35 +0000 Subject: [PATCH] make user able to append extra trace data. The way of logging backtrace is also changed. lket_trace_extra() and lket_backtrace() are introduced for these two purpose. I also modified lket.5.in for the backtrace changes --- ChangeLog | 9 +++- lket.5.in | 26 +++------ parse.cxx | 13 ++++- staptree.cxx | 2 + staptree.h | 1 + tapset/ChangeLog | 10 ---- tapset/LKET/Changelog | 5 ++ tapset/LKET/ioscheduler.stp | 103 ++++++++++-------------------------- tapset/LKET/lket_trace.stp | 45 ++++++++++++---- tapset/LKET/netdev.stp | 21 +++----- tapset/LKET/process.stp | 3 +- tapset/LKET/scsi.stp | 67 ++++++++--------------- tapset/LKET/syscalls.stp | 19 +++---- tapset/LKET/tskdispatch.stp | 21 +++----- translate.cxx | 5 +- 15 files changed, 143 insertions(+), 207 deletions(-) diff --git a/ChangeLog b/ChangeLog index 136c88f8f..4925de67e 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,7 +1,14 @@ +2006-06-01 Li Guanglei + + * parse.cxx, staptree.cxx, staptree.h, translate.cxx: + add new function lket_trace_extra at script level + * lket.5.in: Modified the description of backtrace in + LKET + 2006-05-29 Li Guanglei * systemtap.spec.in: include lket-b2a in the rpm package - + 2006-05-27 Li Guanglei * configure.ac: add conditional build of lket-b2a diff --git a/lket.5.in b/lket.5.in index 52b049e1d..d98092a4c 100644 --- a/lket.5.in +++ b/lket.5.in @@ -217,31 +217,17 @@ Data format is: .SH BACKTRACE -Some event hooks have the capability of print backtrace. But since -backtrace printing is costly, it is defaultly turned off. +You should use lket_backtrace() function to log backtrace for +different events. -To print backtrace, you can just add "backtrace=1" into the probes, e.g: +It's simple to log backtrace, e.g: .SAMPLE probe addevent.scsi.ioentry { - backtrace=1 + lket_backtrace() } .ESAMPLE -By default backtrace=0 - -Currently the following events could be able to print backtrace: -.SAMPLE -.BR addevent.ioscheduler.elv_next_request -.BR addevent.ioscheduler.elv_add_request -.BR addevent.netdev.transmit -.BR addevent.scsi.ioentry -.BR addevent.scsi.iodispatching -.BR addevent.tskdispatch.cpuidle -.BR addevent.syscall.entry -.BR addevent.syscall.return -.ESAMPLE - .SH TRACE DATA FORMAT By default, LKET will log the trace data in binary format. @@ -282,8 +268,8 @@ stap -e "probe addevent.syscall {}" -I /usr/local/share/systemtap/tapsets/LKET - To only probe syscall.entry: stap -e "probe addevent.syscall.entry {}" -I /usr/local/share/systemtap/tapsets/LKET -b -M .TP -To probe netdev transmition and print the backtrace: -stap -e "probe addevent.netdev.transmit { backtrace=1 }" -I /usr/local/share/systemtap/tapsets/LKET -b -M +To probe netdev transmition and log backtrace: +stap -e "probe addevent.netdev.transmit { lket_backtrace() }" -I /usr/local/share/systemtap/tapsets/LKET -b -M .SH SEE ALSO diff --git a/parse.cxx b/parse.cxx index dc711be23..cc1638fa2 100644 --- a/parse.cxx +++ b/parse.cxx @@ -2082,12 +2082,23 @@ parser::parse_symbol () else if (name.size() > 0 && (name == "print" || name == "sprint" || name == "printf" - || name == "sprintf")) + || name == "sprintf" + || name == "lket_trace_extra")) { print_format *fmt = new print_format; fmt->tok = t; fmt->print_with_format = (name[name.size() - 1] == 'f'); fmt->print_to_stream = (name[0] == 'p'); + + fmt->lket_trace_extra = false; + + if(name == "lket_trace_extra") + { + fmt->print_with_format = true; + fmt->print_to_stream = true; + fmt->lket_trace_extra = true; + } + expect_op("("); if (fmt->print_with_format) { diff --git a/staptree.cxx b/staptree.cxx index 676a4ec3b..5ccbc26b3 100644 --- a/staptree.cxx +++ b/staptree.cxx @@ -626,6 +626,7 @@ void print_format::print (ostream& o) const string name = (string(print_to_stream ? "" : "s") + string("print") + string(print_with_format ? "f" : "")); + if(lket_trace_extra) name="lket_trace_extra"; o << name << "("; if (print_with_format) { @@ -2203,6 +2204,7 @@ deep_copy_visitor::visit_print_format (print_format* e) n->tok = e->tok; n->print_with_format = e->print_with_format; n->print_to_stream = e->print_to_stream; + n->lket_trace_extra = e->lket_trace_extra; n->raw_components = e->raw_components; n->components = e->components; for (unsigned i = 0; i < e->args.size(); ++i) diff --git a/staptree.h b/staptree.h index 583a877df..b2512054c 100644 --- a/staptree.h +++ b/staptree.h @@ -261,6 +261,7 @@ struct print_format: public expression { bool print_with_format; bool print_to_stream; + bool lket_trace_extra; enum format_flag { diff --git a/tapset/ChangeLog b/tapset/ChangeLog index b6fea641f..9f4a556f8 100644 --- a/tapset/ChangeLog +++ b/tapset/ChangeLog @@ -37,8 +37,6 @@ 2006-05-25 Li Guanglei - * LKET/*.stp: explicitly add type qualifier for different arch - to make _stp_vsnprintf get the argument by va_arg correctly. * scheduler.stp: add prev_task and next_task variable. 2006-05-24 Josh Stone @@ -69,14 +67,6 @@ * tapset/tskschedule.stp: deleted, merge into scheduler.stp * tapset/scheduler.stp: incorporate tskschedule.stp -2006-05-18 Li Guanglei - - * testsuite/buildok/ioscheduler.stp: testcase for ioscheduler.stp - * testsuite/buildok/memory.stp: testcase for memory.stp - * testsuite/buildok/networking.stp: testcase for networking.stp - * testsuite/buildok/scsi.stp: testcase for scsi.stp - * testsuite/buildok/tskschedule.stp: testcase for tskschedule.stp - 2006-05-17 Josh Stone * process.stp: Rename signal.send to signal_send and process.complete diff --git a/tapset/LKET/Changelog b/tapset/LKET/Changelog index 780ceefee..dbad033f8 100644 --- a/tapset/LKET/Changelog +++ b/tapset/LKET/Changelog @@ -1,3 +1,8 @@ +2006-06-01 Li Guanglei + + * *.stp: make user able to append extra trace data. The + way of logging backtrace is also changed + 2006-05-25 Li Guanglei * hookid_defs.stp, ioscheduler.stp, lket_trace.stp, netdev.stp, diff --git a/tapset/LKET/ioscheduler.stp b/tapset/LKET/ioscheduler.stp index 4d68537c0..462e3758a 100755 --- a/tapset/LKET/ioscheduler.stp +++ b/tapset/LKET/ioscheduler.stp @@ -5,7 +5,6 @@ // Public License (GPL); either version 2, or (at your option) any // later version. -/* only print backtrace for elv_add_request & elv_next_request*/ probe addevent.ioscheduler = addevent.ioscheduler.elv_next_request, addevent.ioscheduler.elv_completed_request, @@ -15,20 +14,20 @@ probe addevent.ioscheduler /* when a request is retrieved from request queue */ probe addevent.ioscheduler.elv_next_request - += ioscheduler.elv_next_request + = ioscheduler.elv_next_request { if(filter_by_pid() == 1 ) { - log_ioscheduler_tracedata_elv_next(HOOKID_IOSCHED_NEXT_REQ, $q, backtrace) + log_ioscheduler_tracedata_elv_next(HOOKID_IOSCHED_NEXT_REQ, $q) } } /* when a request is added to the request queue */ probe addevent.ioscheduler.elv_add_request - += ioscheduler.elv_add_request + = ioscheduler.elv_add_request { if(filter_by_pid() == 1 ) { - log_ioscheduler_tracedata_others(HOOKID_IOSCHED_ADD_REQ, $q, $rq, backtrace) + log_ioscheduler_tracedata_others(HOOKID_IOSCHED_ADD_REQ, $q, $rq) } } @@ -37,7 +36,7 @@ probe addevent.ioscheduler.elv_completed_request = ioscheduler.elv_completed_request { if(filter_by_pid() == 1 ) { - log_ioscheduler_tracedata_others(HOOKID_IOSCHED_REMOVE_REQ, $q, $rq, backtrace) + log_ioscheduler_tracedata_others(HOOKID_IOSCHED_REMOVE_REQ, $q, $rq) } } @@ -50,46 +49,29 @@ probe addevent.ioscheduler.elv_completed_request /* log the data specific to __elv_add_request and elv_remove_request */ %( kernel_v >= "2.6.10" %? -function log_ioscheduler_tracedata_others(var_id:long, var_q:long, var_rq:long, backtrace:long) +function log_ioscheduler_tracedata_others(var_id:long, var_q:long, var_rq:long) %{ struct request *rq = (struct request *)((long)THIS->var_rq); struct request_queue *q = (struct request_queue *)((long)THIS->var_q); /* elevator name|major|minor| */ - /* only print backtrace for elv_add_request */ - if(THIS->backtrace == 1) { - String str = _stp_string_init (0); - _stp_stack_sprint (str, CONTEXT->regs, 0); - - _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b%0s", q->elevator->elevator_type->elevator_name, - (_FMT_)rq->rq_disk->major, (_FMT_)rq->rq_disk->first_minor, _stp_string_ptr(str)); - } else { - _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b", q->elevator->elevator_type->elevator_name, - (_FMT_)rq->rq_disk->major, (_FMT_)rq->rq_disk->first_minor); - } + _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b", + q->elevator->elevator_type->elevator_name, + (_FMT_)rq->rq_disk->major, (_FMT_)rq->rq_disk->first_minor); %} %: -function log_ioscheduler_tracedata_others(var_id:long, var_q:long, var_rq:long, backtrace:long) +function log_ioscheduler_tracedata_others(var_id:long, var_q:long, var_rq:long) %{ struct request *rq = (struct request *)((long)THIS->var_rq); struct request_queue *q = (struct request_queue *)((long)THIS->var_q); /* elevator name|major|minor| */ - /* only print backtrace for elv_add_request */ - if(THIS->backtrace == 1) { - String str = _stp_string_init (0); - _stp_stack_sprint (str, CONTEXT->regs, 0); - - _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b%0s", q->elevator.elevator_name, - (_FMT_)rq->rq_disk->major, (_FMT_)rq->rq_disk->first_minor, _stp_string_ptr(str)); - } else { - _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b", q->elevator.elevator_name, - (_FMT_)rq->rq_disk->major, (_FMT_)rq->rq_disk->first_minor); - } + _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b", q->elevator.elevator_name, + (_FMT_)rq->rq_disk->major, (_FMT_)rq->rq_disk->first_minor); %} %) @@ -98,7 +80,7 @@ function log_ioscheduler_tracedata_others(var_id:long, var_q:long, var_rq:long, %( kernel_v >= "2.6.10" %? /* log the data specific to elv_next_request , for kernel > 2.6.9*/ -function log_ioscheduler_tracedata_elv_next(var_id:long, var:long, backtrace:long) +function log_ioscheduler_tracedata_elv_next(var_id:long, var:long) %{ struct request_queue *q; @@ -112,36 +94,21 @@ function log_ioscheduler_tracedata_elv_next(var_id:long, var:long, backtrace:lon elevator name|empty| */ - if(THIS->backtrace == 1) { - String str = _stp_string_init (0); - _stp_stack_sprint (str, CONTEXT->regs, 0); - - if(list_empty(&(q->queue_head))) { - _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b%0s", - q->elevator->elevator_type->elevator_name, (_FMT_)-1, (_FMT_)-1, _stp_string_ptr(str)); - } else { - rq = list_entry_rq(q->queue_head.next); - _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b%0s", - q->elevator->elevator_type->elevator_name, (_FMT_)rq->rq_disk->major, - (_FMT_)rq->rq_disk->first_minor, _stp_string_ptr(str)); - } + if(list_empty(&(q->queue_head))) { + _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b", + q->elevator->elevator_type->elevator_name, (_FMT_)-1, (_FMT_)-1); } else { - if(list_empty(&(q->queue_head))) { - _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b", - q->elevator->elevator_type->elevator_name, (_FMT_)-1, (_FMT_)-1); - } else { - rq = list_entry_rq(q->queue_head.next); - _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b", - q->elevator->elevator_type->elevator_name, (_FMT_)rq->rq_disk->major, - (_FMT_)rq->rq_disk->first_minor); - } - + rq = list_entry_rq(q->queue_head.next); + _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b", + q->elevator->elevator_type->elevator_name, (_FMT_)rq->rq_disk->major, + (_FMT_)rq->rq_disk->first_minor); } + %} %: -function log_ioscheduler_tracedata_elv_next(var_id:long, var:long, backtrace:long) +function log_ioscheduler_tracedata_elv_next(var_id:long, var:long) %{ struct request_queue *q; @@ -154,27 +121,13 @@ function log_ioscheduler_tracedata_elv_next(var_id:long, var:long, backtrace:lon if there is no request in the request queue: elevator name|empty| */ - if(THIS->backtrace == 1) { - String str = _stp_string_init (0); - _stp_stack_sprint (str, CONTEXT->regs, 0); - - if(list_empty(&(q->queue_head))) { - _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b%0s", - q->elevator.elevator_name, (_FMT_)-1, (_FMT_)-1, _stp_string_ptr(str)); - } else { - rq = list_entry_rq(q->queue_head.next); - _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b%0s", q->elevator.elevator_name, - (_FMT_)rq->rq_disk->major, (_FMT_)rq->rq_disk->first_minor, _stp_string_ptr(str)); - } + if(list_empty(&(q->queue_head))) { + _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b", + q->elevator.elevator_name, (_FMT_)-1, (_FMT_)-1); } else { - if(list_empty(&(q->queue_head))) { - _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b", - q->elevator.elevator_name, (_FMT_)-1, (_FMT_)-1); - } else { - rq = list_entry_rq(q->queue_head.next); - _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b", q->elevator.elevator_name, - (_FMT_)rq->rq_disk->major, (_FMT_)rq->rq_disk->first_minor); - } + rq = list_entry_rq(q->queue_head.next); + _lket_trace(_GROUP_IOSCHED, THIS->var_id, "%0s%1b%1b", q->elevator.elevator_name, + (_FMT_)rq->rq_disk->major, (_FMT_)rq->rq_disk->first_minor); } %} diff --git a/tapset/LKET/lket_trace.stp b/tapset/LKET/lket_trace.stp index 5e3739d46..851a3163d 100755 --- a/tapset/LKET/lket_trace.stp +++ b/tapset/LKET/lket_trace.stp @@ -50,19 +50,23 @@ function lket_trace_init() #ifndef __LKET_TRACE__ #define __LKET_TRACE__ -#define STP_BIN_PACKET 1 +#define LKET_PKT_SYS 1 +#define LKET_PKT_BT 2 +#define LKET_PKT_USER 3 #define MAX_FMT_LEN 128 -char newfmt[MAX_FMT_LEN] = "\n%d|%d|%d|%d|%d|%d|%d|%d"; -#define NEW_FMT_START 24 +char new_sysfmt[MAX_FMT_LEN] = "\n%d|%d|%d|%d|%d|%d|%d|%d"; +char new_userfmt[MAX_FMT_LEN] = "| USER:"; +#define NEW_SYSFMT_START 24 +#define NEW_USERFMT_START 7 -void fmt_change(char *oldfmt) +void fmt_change(char *oldfmt, char *newfmt, int newfmt_start) { char *old_ptr, *new_ptr; old_ptr = oldfmt; - new_ptr = newfmt + NEW_FMT_START; + new_ptr = newfmt + newfmt_start; while(*old_ptr != 0 && (new_ptr - newfmt) < MAX_FMT_LEN) { if(*old_ptr != '%') { @@ -112,13 +116,19 @@ void fmt_change(char *oldfmt) #define _lket_trace(GroupID, hookID, fmt, args...) do { \ struct timeval tv; \ do_gettimeofday (&tv); \ - fmt_change(fmt); \ - _stp_printf(newfmt, \ + fmt_change(fmt, new_sysfmt, NEW_SYSFMT_START); \ + _stp_printf(new_sysfmt, \ (_FMT_)GroupID, (_FMT_)hookID, (_FMT_)tv.tv_sec, (_FMT_)tv.tv_usec,\ (_FMT_)current->tgid, (_FMT_)current->parent->pid,\ (_FMT_)current->pid, (_FMT_)current->thread_info->cpu, args);\ } while(0) +#define _lket_trace_extra(fmt, args...) do {\ + fmt_change(fmt, new_userfmt, NEW_USERFMT_START);\ + _stp_printf(new_userfmt, args);\ +} while(0) + + #else //binary trace static inline int this_event_len(void) @@ -126,17 +136,34 @@ static inline int this_event_len(void) return 0; } -/* we use 2 bytes to store the length. 256 may be not enough for backtrace event */ +/* we use 2 bytes to store the length. */ #define _lket_trace(GroupID, hookID, fmt, args...) do { \ struct timeval tv; \ do_gettimeofday (&tv); \ _stp_printf("%1b%2n%1b%1b%4b%4b%4b%4b%4b%1b"fmt, \ - (_FMT_)STP_BIN_PACKET, (_FMT_)GroupID, (_FMT_)hookID, \ + (_FMT_)LKET_PKT_SYS, (_FMT_)GroupID, (_FMT_)hookID, \ (_FMT_)tv.tv_sec, (_FMT_)tv.tv_usec, (_FMT_)current->tgid, \ (_FMT_)current->parent->pid, (_FMT_)current->pid, \ (_FMT_)current->thread_info->cpu, args);\ } while(0) +#define _lket_trace_extra(fmt, args...) do {\ + _stp_printf("%1b%2n%0s"fmt, (_FMT_)LKET_PKT_USER, fmt, args);\ +} while(0) + +#endif #endif +%} + + +function lket_backtrace () %{ + if (CONTEXT->regs) { + String str = _stp_string_init (0); + _stp_stack_sprint (str, CONTEXT->regs, 0); +#if defined(ASCII_TRACE) + _stp_printf("|BACKTRACE: %s", _stp_string_ptr(str)); +#else + _stp_printf("%1b%2n%0s", (_FMT_)LKET_PKT_BT, _stp_string_ptr(str)); #endif + } %} diff --git a/tapset/LKET/netdev.stp b/tapset/LKET/netdev.stp index 9c79d0363..024e869c8 100755 --- a/tapset/LKET/netdev.stp +++ b/tapset/LKET/netdev.stp @@ -19,19 +19,19 @@ probe addevent.netdev.receive = netdev.receive { /* no need to filter by pid */ - log_netdev_extra(HOOKID_NETDEV_RECEIVE,$skb, backtrace) + log_netdev_extra(HOOKID_NETDEV_RECEIVE,$skb) } /* Queue a buffer for transmission to a network device */ probe addevent.netdev.transmit - += netdev.transmit + = netdev.transmit { if(filter_by_pid() == 1 ) { - log_netdev_extra(HOOKID_NETDEV_TRANSMIT, $skb, backtrace) + log_netdev_extra(HOOKID_NETDEV_TRANSMIT, $skb) } } -function log_netdev_extra(var_id:long, var:long, backtrace:long) +function log_netdev_extra(var_id:long, var:long) %{ struct sk_buff *skb = (struct sk_buff *)((long)THIS->var); @@ -52,15 +52,6 @@ function log_netdev_extra(var_id:long, var:long, backtrace:long) 86DD IPv6 */ - /* only print backtrace for netdev.transmit */ - if(THIS->backtrace == 1) { - String str = _stp_string_init (0); - _stp_stack_sprint (str, CONTEXT->regs, 0); - - _lket_trace(_GROUP_NETDEV, THIS->var_id, "%0s%4b%2b%4b%0s", skb->dev->name, - (_FMT_)skb->len, (_FMT_)skb->protocol, (_FMT_)skb->truesize, _stp_string_ptr(str)); - } else { - _lket_trace(_GROUP_NETDEV, THIS->var_id, "%0s%4b%2b%4b", skb->dev->name, - (_FMT_)skb->len, (_FMT_)skb->protocol, (_FMT_)skb->truesize); - } + _lket_trace(_GROUP_NETDEV, THIS->var_id, "%0s%4b%2b%4b", skb->dev->name, + (_FMT_)skb->len, (_FMT_)skb->protocol, (_FMT_)skb->truesize); %} diff --git a/tapset/LKET/process.stp b/tapset/LKET/process.stp index 039847b33..9a8e2196f 100755 --- a/tapset/LKET/process.stp +++ b/tapset/LKET/process.stp @@ -36,7 +36,8 @@ function process_snapshot() name for each entry */ list_for_each(cur, head) { tsk = (struct task_struct *)(list_entry(cur, struct task_struct, tasks)); - _lket_trace(_GROUP_PROCESS, _HOOKID_PROCESS_SNAPSHOT, "%4b%0s", (_FMT_)tsk->pid, tsk->comm); + _lket_trace(_GROUP_PROCESS, _HOOKID_PROCESS_SNAPSHOT, "%4b%0s", + (_FMT_)tsk->pid, tsk->comm); _stp_print_flush(); } %} diff --git a/tapset/LKET/scsi.stp b/tapset/LKET/scsi.stp index d6e254e05..b98e43469 100755 --- a/tapset/LKET/scsi.stp +++ b/tapset/LKET/scsi.stp @@ -33,16 +33,16 @@ probe addevent.scsi /* mid-layer prepare a IO request */ probe addevent.scsi.ioentry - += scsi.ioentry + = scsi.ioentry { - log_scsi_ioentry(HOOKID_SCSI_IOENTRY, $q, $req, backtrace) + log_scsi_ioentry(HOOKID_SCSI_IOENTRY, $q, $req) } /* Dispatch a command to the low-level driver. */ probe addevent.scsi.iodispatching - += scsi.iodispatching + = scsi.iodispatching { - log_scsi_dispatch(HOOKID_SCSI_IO_TO_LLD, $cmd, backtrace) + log_scsi_dispatch(HOOKID_SCSI_IO_TO_LLD, $cmd) } /* I/O is done by low-level driver*/ @@ -66,7 +66,7 @@ probe addevent.scsi.iocompleted } /* log the info about scsi io entry */ -function log_scsi_ioentry(var_id:long, var_q:long, var_rq:long, backtrace:long) +function log_scsi_ioentry(var_id:long, var_q:long, var_rq:long) %{ struct request_queue *q = (struct request_queue *)((long)THIS->var_q); struct request *rq = (struct request *)((long)THIS->var_rq); @@ -75,15 +75,8 @@ function log_scsi_ioentry(var_id:long, var_q:long, var_rq:long, backtrace:long) /* major|minor|scsi_device_state| */ - if(THIS->backtrace == 1) { - String str = _stp_string_init (0); - _stp_stack_sprint (str, CONTEXT->regs, 0); - _lket_trace(_GROUP_SCSI, THIS->var_id, "%1b%1b%1b%0s", (_FMT_)rq->rq_disk->major, - (_FMT_)rq->rq_disk->first_minor, (_FMT_)sdev->sdev_state, _stp_string_ptr(str)); - } else { - _lket_trace(_GROUP_SCSI, THIS->var_id, "%1b%1b%1b", (_FMT_)rq->rq_disk->major, - (_FMT_)rq->rq_disk->first_minor, (_FMT_)sdev->sdev_state); - } + _lket_trace(_GROUP_SCSI, THIS->var_id, "%1b%1b%1b", (_FMT_)rq->rq_disk->major, + (_FMT_)rq->rq_disk->first_minor, (_FMT_)sdev->sdev_state); %} /* log the info about scsi_dispatching_cmd @@ -109,7 +102,7 @@ function log_scsi_ioentry(var_id:long, var_q:long, var_rq:long, backtrace:long) /* sdev_state|scsi_info|data_direction|request_buffer|request_bufflen|cmd_identifier| */ %( kernel_v >= "2.6.12" %? -function log_scsi_dispatch(var_id:long, var:long, backtrace:long) +function log_scsi_dispatch(var_id:long, var:long) %{ struct scsi_cmnd *cmd = (struct scsi_cmnd *)((long)THIS->var); int scsi_info; @@ -125,24 +118,14 @@ function log_scsi_dispatch(var_id:long, var:long, backtrace:long) * Instead of skipping SDEV_DEL & SDEV_BLOCK, I choose to log them */ - if(THIS->backtrace == 1) { - String str = _stp_string_init (0); - _stp_stack_sprint (str, CONTEXT->regs, 0); - - _lket_trace(_GROUP_SCSI, THIS->var_id, "%1b%4b%1b%8b%4b%8b%0s", (_FMT_)cmd->device->sdev_state, - (_FMT_)scsi_info, (_FMT_)cmd->sc_data_direction, (int64_t)((long)cmd->request_buffer), - (_FMT_)cmd->request_bufflen, (int64_t)cmd->device->host->cmd_pid, _stp_string_ptr(str)); - } else { - - _lket_trace(_GROUP_SCSI, THIS->var_id, "%1b%4b%1b%8b%4b%8b", (_FMT_)cmd->device->sdev_state, - (_FMT_)scsi_info, (_FMT_)cmd->sc_data_direction, (int64_t)((long)cmd->request_buffer), - (_FMT_)cmd->request_bufflen, (int64_t)cmd->device->host->cmd_pid); - } - + _lket_trace(_GROUP_SCSI, THIS->var_id, "%1b%4b%1b%8b%4b%8b", + (_FMT_)cmd->device->sdev_state, (_FMT_)scsi_info, + (_FMT_)cmd->sc_data_direction, (int64_t)((long)cmd->request_buffer), + (_FMT_)cmd->request_bufflen, (int64_t)cmd->device->host->cmd_pid); %} %: -function log_scsi_dispatch(var_id:long, var:long, backtrace:long) +function log_scsi_dispatch(var_id:long, var:long) %{ struct scsi_cmnd *cmd = (struct scsi_cmnd *)((long)THIS->var); int scsi_info; @@ -161,18 +144,10 @@ function log_scsi_dispatch(var_id:long, var:long, backtrace:long) /* systemTap failed to access global variable. So I temporarily use 0. _stp_printf("%d|", scsi_pid); */ - if(THIS->backtrace == 1) { - String str = _stp_string_init (0); - _stp_stack_sprint (str, CONTEXT->regs, 0); - - _lket_trace(_GROUP_SCSI, THIS->var_id, "%1b%4b%1b%8b%4b%8b%0s", (_FMT_)cmd->device->sdev_state, - (_FMT_)scsi_info, (_FMT_)cmd->sc_data_direction, (int64_t)((long)cmd->request_buffer), - (_FMT_)cmd->request_bufflen, (int64_t)0, _stp_string_ptr(str)); - } else { - _lket_trace(_GROUP_SCSI, THIS->var_id, "%1b%4b%1b%8b%4b%8b", (_FMT_)cmd->device->sdev_state, - (_FMT_)scsi_info, (_FMT_)cmd->sc_data_direction, (int64_t)((long)cmd->request_buffer), - (_FMT_)cmd->request_bufflen, (int64_t)0); - } + _lket_trace(_GROUP_SCSI, THIS->var_id, "%1b%4b%1b%8b%4b%8b", + (_FMT_)cmd->device->sdev_state, (_FMT_)scsi_info, + (_FMT_)cmd->sc_data_direction, (int64_t)((long)cmd->request_buffer), + (_FMT_)cmd->request_bufflen, (int64_t)0); %} %) @@ -188,8 +163,8 @@ function log_scsi_iodone_extra(var_id:long, var:long) (cmd->device->id & 0xFF); /* scsi_info|data_direction|cmd_identifier| */ - _lket_trace(_GROUP_SCSI, THIS->var_id, "%4b%1b%8b", (_FMT_)scsi_info, (_FMT_)cmd->sc_data_direction, - (int64_t)cmd->pid); + _lket_trace(_GROUP_SCSI, THIS->var_id, "%4b%1b%8b", (_FMT_)scsi_info, + (_FMT_)cmd->sc_data_direction, (int64_t)cmd->pid); %} /* log the info about scsi_dispatching_cmd */ @@ -205,6 +180,6 @@ function log_scsi_iocompleted(var_id:long, var_cmd:long, var_goodbytes:long) (cmd->device->id & 0xFF); /* scsi_info|data_direction|cmd_identifier|goodbytes */ - _lket_trace(_GROUP_SCSI, THIS->var_id, "%4b%1b%8b%4b", (_FMT_)scsi_info, (_FMT_)cmd->sc_data_direction, - (int64_t)cmd->pid, (_FMT_)goodbytes); + _lket_trace(_GROUP_SCSI, THIS->var_id, "%4b%1b%8b%4b", (_FMT_)scsi_info, + (_FMT_)cmd->sc_data_direction, (int64_t)cmd->pid, (_FMT_)goodbytes); %} diff --git a/tapset/LKET/syscalls.stp b/tapset/LKET/syscalls.stp index 7215f4f5e..7b4f6799f 100755 --- a/tapset/LKET/syscalls.stp +++ b/tapset/LKET/syscalls.stp @@ -11,31 +11,24 @@ probe addevent.syscall } /* log the system call name */ -function log_syscall_tracedata(var_id:long, name:string, backtrace:long) +function log_syscall_tracedata(var_id:long, name:string) %{ - if(THIS->backtrace == 1) { - String str = _stp_string_init (0); - _stp_stack_sprint (str, CONTEXT->regs, 0); - - _lket_trace(_GROUP_SYSCALL, THIS->var_id, "%0s%0s", THIS->name, _stp_string_ptr(str)); - } else { - _lket_trace(_GROUP_SYSCALL, THIS->var_id, "%0s", THIS->name); - } + _lket_trace(_GROUP_SYSCALL, THIS->var_id, "%0s", THIS->name); %} probe addevent.syscall.entry - += syscall.* + = syscall.* { if(filter_by_pid() == 1 ) { - log_syscall_tracedata(HOOKID_SYSCALL_ENTRY, name, backtrace) + log_syscall_tracedata(HOOKID_SYSCALL_ENTRY, name) } } probe addevent.syscall.return - += syscall.*.return + = syscall.*.return { if(filter_by_pid() == 1 ) { - log_syscall_tracedata(HOOKID_SYSCALL_RETURN, name, backtrace) + log_syscall_tracedata(HOOKID_SYSCALL_RETURN, name) } } diff --git a/tapset/LKET/tskdispatch.stp b/tapset/LKET/tskdispatch.stp index 9cc3bf4f4..f75c083a6 100755 --- a/tapset/LKET/tskdispatch.stp +++ b/tapset/LKET/tskdispatch.stp @@ -23,12 +23,12 @@ probe addevent.tskdispatch /* Only applicable to SMP systems */ probe addevent.tskdispatch.cpuidle - += scheduler.balance + = scheduler.balance { /* we didn't call filter_by_pid() here, so that we can get all the idle events despite how the cpu enters idle */ - log_cpuidle_tracedata(HOOKID_TASK_CPUIDLE, backtrace) + log_cpuidle_tracedata(HOOKID_TASK_CPUIDLE) } probe addevent.tskdispatch.ctxswitch @@ -51,22 +51,13 @@ function log_ctxswitch_tracedata(var_id:long, prev:long, next_pid:long) prev_tsk = (struct task_struct *)((long)THIS->prev); next_tsk = (struct task_struct *)((long)THIS->next_pid); - _lket_trace(_GROUP_TASK, THIS->var_id, "%4b%4b%1b", (_FMT_)prev_tsk->pid, (_FMT_)next_tsk->pid, - (_FMT_)prev_tsk->state); + _lket_trace(_GROUP_TASK, THIS->var_id, "%4b%4b%1b", (_FMT_)prev_tsk->pid, + (_FMT_)next_tsk->pid, (_FMT_)prev_tsk->state); %} -function log_cpuidle_tracedata(var_id:long, backtrace:long) +function log_cpuidle_tracedata(var_id:long) %{ struct task_struct *cur = current; - if(THIS->backtrace == 1) { - String str = _stp_string_init (0); - _stp_stack_sprint (str, CONTEXT->regs, 0); - _lket_trace(_GROUP_TASK, THIS->var_id, "%4b%0s", (_FMT_)cur->pid, _stp_string_ptr(str)); - } else { - _lket_trace(_GROUP_TASK, THIS->var_id, "%4b", (_FMT_)cur->pid); - } + _lket_trace(_GROUP_TASK, THIS->var_id, "%4b", (_FMT_)cur->pid); %} - - - diff --git a/translate.cxx b/translate.cxx index 30d3bd626..2ee2aac29 100644 --- a/translate.cxx +++ b/translate.cxx @@ -3591,7 +3591,10 @@ c_unparser::visit_print_format (print_format* e) if (e->print_to_stream) { o->newline() << res.qname() << " = 0;"; - o->newline() << "_stp_printf ("; + if(e->lket_trace_extra) + o->newline() << "_lket_trace_extra ("; + else + o->newline() << "_stp_printf ("; } else o->newline() << "_stp_snprintf (" << res.qname() << ", MAXSTRINGLEN, "; -- 2.43.5