- Tracebuffer/tracepoint changes improvements:

- Add a scientific notion when printing cycles and pmcs (4 digts + exponent)
 - Increase number of characters after which tracebuffer wraps around
 - Add a tsc filter for dumping tb entries
 - Add a function to dump tracebuffer automatically (tbuf_dump), e.g.
   periodically during timer interrupt
 - Take user tracepoints into account when enabling un-detailed tracing of
   records
 - Allow tp id filter to accept user ids
 - Fix K8 tracebuffer pmcs
 - When recording a tbuf entry, first record pmcs then (finally) the tsc
 - Start tracepoint detail levels with bit 0
 - Allow tracepoint to enter kdb without printing something on the console
 - Use TRACEPOINT_DETAIL for detailed tracing
 - Add some TRACE_..._DETAILS macros
 - Coalesce TRACE_... macros in tracepoints.h
This commit is contained in:
Jan Stoess 2008-01-25 16:22:15 +01:00
parent 50f4602adf
commit 50f174c618
12 changed files with 314 additions and 176 deletions

View File

@ -36,12 +36,13 @@
#include <kdb/tracebuffer.h>
#include INC_API(thread.h)
#include INC_API(tcb.h)
#include INC_GLUE(timer.h)
#if defined(CONFIG_TRACEBUFFER)
FEATURESTRING ("tracebuffer");
#define TB_WRAP 50
#define TB_WRAP 60
extern void list_tp_choices (void);
#if defined(CONFIG_TBUF_PERFMON)
@ -50,19 +51,54 @@ extern void list_tp_choices (void);
#define IF_PERFMON(a...)
#endif
extern word_t local_apic_cpu_mhz;
static inline int SECTION(SEC_KDEBUG) strlen(const char* p) { int i=0; while (*(p++)) i++; return i; };
extern void putc(const char c);
static inline void pmc_print(word_t pmc)
template<typename T> static void pmc_print(T pmc)
{
/* estimate number of spaces and digits */
if (pmc > 1000000)
printf("%-4uM ", pmc / 1000000);
else if (pmc > 1000)
printf("%-4uK ", pmc / 1000);
else
printf("%-5u ", pmc);
T divisor = 0;
int digits = 0, num = 0;
const int width = 4;
/* calculate number of digits */
if (pmc == 0)
digits = 0;
else
for (divisor = 1, digits = 1; pmc/divisor >= 10; divisor *= 10, digits++);
while (num < max(width - digits, 0))
{
putc('0');
num++;
}
while (num < width)
{
ASSERT(divisor);
char d = (pmc/divisor) % 10;
putc(d + '0');
divisor /= 10;
num++;
}
if (digits > width)
{
putc('e');
putc(digits-width + '0');
}
else
{
putc(' ');
putc(' ');
}
putc(' ');
}
template<typename T> T pmc_delta(T cur, T old)
@ -85,7 +121,8 @@ private:
tcb_t *tcb[max_filters];
word_t typemask;
word_t cpumask;
u64_t tsc;
bool cpu_pass(tracerecord_t *t)
{
return ((cpumask & (1UL << t->cpu)) != 0);
@ -96,6 +133,14 @@ private:
return (typemask & ((t->ktype << 16) | t->utype));
}
bool tsc_pass(tracerecord_t *t)
{
if (tsc == 0) return true;
u64_t ttsc = t->tsc;
return (ttsc >= tsc);
}
bool id_pass(tracerecord_t *t)
{
@ -137,13 +182,13 @@ public:
void invalidate_filters()
{
get_tracebuffer()->mask = 0xffffffff;
for (word_t i=0; i < max_filters; i++)
{
id[i] = NULL;
tcb[i] = NULL;
}
cpumask = typemask = ~0UL;
tsc = 0;
}
@ -156,7 +201,7 @@ public:
printf("Display filters:\n");
printf("\tCPU: [%x]\n", cpumask);
printf("\tTypemask: [%x]\n", typemask);
printf("\tTSC: [%x/%x]\n", (u32_t) (tsc >> 32), (u32_t) tsc);
printf("\tTracepoints: \n");
for (word_t i=0; i < max_filters; i++)
{
@ -183,7 +228,9 @@ public:
void set_typemask(word_t mask) { typemask = mask; }
word_t get_typemask() { return this->typemask; }
void set_tsc(u64_t t) { tsc = t; }
u64_t get_tsc() { return this->tsc; }
void set_id(word_t idx, word_t id)
{
ASSERT(idx < max_filters);
@ -204,14 +251,16 @@ public:
}
bool pass(tracerecord_t *t)
{ return cpu_pass(t) && type_pass(t) && id_pass(t) && tcb_pass(t); }
{ return cpu_pass(t) && type_pass(t) && id_pass(t) && tsc_pass(t) && tcb_pass(t); }
/* Tbuf handling */
void set_tbuf_type_mask(word_t mask)
{
get_tracebuffer()->mask = mask;
}
void set_tbuf_typemask(word_t mask)
{ get_tracebuffer()->mask = mask; }
word_t get_tbuf_typemask()
{ return get_tracebuffer()->mask; }
word_t get_tbuf_size()
{ return (TRACEBUFFER_SIZE / sizeof (tracerecord_t)) - 1; }
@ -256,15 +305,19 @@ public:
{
if (start > size) start = size;
if (!pass(get_tracebuffer()->tracerecords + start))
tracerecord_t *rec = get_tracebuffer()->tracerecords + start;
if (!pass(rec))
{
//if (rec->tsc && !tsc_pass(rec))
//break;
//else
continue;
}
count--;
}
return start;
}
word_t find_tbuf_end(word_t start, word_t count, word_t size)
{
word_t end, num;
@ -280,7 +333,7 @@ public:
}
return end;
}
bool is_tbuf_valid()
{
tracebuffer_t * tracebuffer = get_tracebuffer ();
@ -309,19 +362,20 @@ public:
word_t num, index;
tracerecord_t * rec;
tracebuffer_t * tracebuffer = get_tracebuffer ();
space_t *kspace = get_kernel_space();
bool printed = false;
space_t * space = get_current_space ();
struct {
word_t tsc;
word_t pmc0;
word_t pmc1;
u64_t pmc0;
u64_t pmc1;
} old[CONFIG_SMP_MAX_CPUS], sum = { 0, 0, 0 };
for (word_t cpu = 0; cpu < CONFIG_SMP_MAX_CPUS; cpu++)
old[cpu].tsc = old[cpu].pmc0 = old[cpu].pmc1 = 0;
if (header)
printf ("\nRecord P Type TP %ws TSC " IF_PERFMON (" PMC0 PMC1 ") " Event\n",
printf ("\nRecord P Type TP %ws TSC " IF_PERFMON (" PMC0 PMC1 ") " Event\n",
"Thread");
for (num = 1, index = start; count--; index++)
@ -332,51 +386,66 @@ public:
if (!pass(rec))
continue;
word_t cpu = rec->cpu;
if (((++num % 4000) == 0) && get_choice ("Continue", "y/n", 'y') == 'n')
break;
if (! old[cpu].tsc)
if (!old[cpu].tsc)
{
old[cpu].tsc = rec->tsc;
IF_PERFMON (old[cpu].pmc0 = rec->pmc0);
IF_PERFMON (old[cpu].pmc1 = rec->pmc1);
}
u64_t c_delta = pmc_delta(rec->tsc, old[cpu].tsc);
if (!header && !c_delta)
continue;
printed = true;
tcb_t * tcb;
threadid_t tid;
if (rec->is_kernel_event ())
{
tcb_t *tcb = addr_to_tcb((addr_t) rec->thread);
if (!kspace->is_tcb_area (tcb) && tcb != get_idle_tcb())
tcb = kspace->get_tcb (threadid ((word_t) tcb));
tid = tcb->get_global_id ();
tcb = addr_to_tcb((addr_t) rec->thread);
tid = tcb->get_global_id();
printf ("%6d %01d %04x %c %4d %wt ", index, rec->cpu, rec->get_type
(), rec->is_kernel_event () ? 'k' : 'u', rec->id, tcb);
}
else
{
tid = threadid (rec->thread);
tcb = space->get_tcb (tid);
printf ("%6d %01d %04x %c %4d %wt ", index, rec->cpu, rec->get_type
(), rec->is_kernel_event () ? 'k' : 'u', rec->id, tid.get_raw ());
}
printf ("%6d %01d %04x %c %3d %wt ", index, rec->cpu, rec->get_type
(), rec->is_kernel_event () ? 'k' : 'u', rec->id, tid.get_raw ());
word_t tscdelta = pmc_delta(rec->tsc, old[cpu].tsc);
pmc_print(tscdelta);
#if defined(CONFIG_TBUF_PERFMON)
word_t pmcdelta0 = pmc_delta(rec->pmc0, old[cpu].pmc0);
word_t pmcdelta1 = pmc_delta(rec->pmc1, old[cpu].pmc1);
// User and kernel instructions
word_t pmcdelta0 = pmc_delta(rec->pmc0, (word_t) old[cpu].pmc0);
word_t pmcdelta1 = pmc_delta(rec->pmc1, (word_t) old[cpu].pmc1);
pmc_print(c_delta);
pmc_print(pmcdelta0);
pmc_print(pmcdelta1);
sum.pmc0 += pmcdelta0;
sum.pmc1 += pmcdelta1;
old[cpu].pmc0 = rec->pmc0;
old[cpu].pmc1 = rec->pmc1;
#else
pmc_print(c_delta);
#endif
sum.tsc += (rec->tsc - old[cpu].tsc);
@ -402,8 +471,9 @@ public:
*dst++ = '\n'; *dst++ = '\t';
*dst++ = '\t'; *dst++ = '\t';
*dst++ = '\t'; *dst++ = '\t';
*dst++ = '\t' ; *dst++ = ' ';
idx+=8;
*dst++ = '\t'; *dst++ = ' ';
*dst++ = ' ' ; *dst++ = ' ';
idx+=10;
if (fid) *dst++ = '%';
}
}
@ -414,9 +484,6 @@ public:
// the space of the thread. We don't really bother too
// much if this does not work.
space_t * space = get_current_space ();
tcb_t * tcb = space->get_tcb (tid);
// Check if we seem to have a valid space and string pointer
if (tcb->get_global_id () != tid ||
@ -449,7 +516,8 @@ public:
*dst++ = '\t'; *dst++ = '\t';
*dst++ = '\t'; *dst++ = '\t';
*dst++ = '\t'; *dst++ = ' ';
idx+=8;
*dst++ = ' ' ; *dst++ = ' ';
idx+=10;
if (fid) *dst++ = '%';
}
// Turn '%s' into '%p' (i.e., avoid printing arbitrary
@ -488,12 +556,18 @@ public:
if (header)
{
printf ("---------------------------------"
IF_PERFMON ("--------------------") "\n");
printf ("Mask %08x %10d" IF_PERFMON ("%10d %10d") " %d entries",
tracebuffer->mask, sum.tsc, IF_PERFMON (sum.pmc0, sum.pmc1,) num-1);
printf ("-------------------------------------------"
IF_PERFMON ("--------------------") "\n");
printf ("Mask %08x ", tracebuffer->mask);
pmc_print(sum.tsc);
IF_PERFMON (pmc_print(sum.pmc0));
IF_PERFMON (pmc_print(sum.pmc1));
printf(" %d entries", num-1);
}
printf("\n");
if (printed)
printf("\n");
}
@ -503,6 +577,55 @@ public:
tbuf_handler_t tbuf_handler;
void tbuf_dump (word_t count, word_t usec, word_t tp_id, word_t cpumask)
{
word_t start, end, size;
word_t old_tp_id[tbuf_handler_t::max_filters];
word_t old_cpumask = tbuf_handler.get_cpumask();
word_t old_typemask = tbuf_handler.get_typemask();
u64_t old_tsc = tbuf_handler.get_tsc();
word_t old_tbuf_typemask = tbuf_handler.get_tbuf_typemask();
tbuf_handler.set_cpumask(cpumask);
tbuf_handler.set_tbuf_typemask(~0ULL);
tbuf_handler.set_typemask(~0ULL);
for (word_t i=0; i < tbuf_handler_t::max_filters; i++)
{
old_tp_id[i] = tbuf_handler.get_id(i);
tbuf_handler.set_id(i, 0);
}
tbuf_handler.set_id(0, tp_id);
size = tbuf_handler.get_tbuf_size();
end = tbuf_handler.get_tbuf_current();
if (usec)
{
u64_t tsc = x86_rdtsc() - ((u64_t) usec * (u64_t) (get_timer()->get_proc_freq() / 1000));
count = size;
tbuf_handler.set_tsc(tsc);
}
start = tbuf_handler.find_tbuf_start(end, count, size);
count = (end >= start) ? end - start : end + size - start;
tbuf_handler.dump_tbuf(start, count, size, false);
if (tp_id)
{
for (word_t i=0; i < tbuf_handler_t::max_filters; i++)
tbuf_handler.set_id(i, old_tp_id[i]);
}
tbuf_handler.set_cpumask(old_cpumask);
tbuf_handler.set_typemask(old_typemask);
tbuf_handler.set_tsc(old_tsc);
tbuf_handler.set_tbuf_typemask(old_tbuf_typemask);
}
/*
* Submenu for tracebuffer related commands.
*/
@ -559,7 +682,7 @@ CMD (cmd_tb_dump_ctr, cg)
* Apply filter for tracebuffer events.
*/
word_t get_type_mask()
word_t get_typemask()
{
word_t mask = 0;
@ -573,10 +696,10 @@ word_t get_type_mask()
mask = 0xffff0000;
break;
case 'n':
mask = 0xffffffff & ~(TP_DEFAULT | TP_DETAIL << 16);
mask = 0xfffcffff;
break;
case 'd':
mask = 0xffffffff & ~(TP_DETAIL << 16);
mask = 0x00010001;
break;
case 'u':
mask = 0x0000ffff;
@ -594,7 +717,7 @@ DECLARE_CMD (cmd_tb_type_filter, tracebuf, 'f', "filter", "Record filter");
CMD (cmd_tb_type_filter, cg)
{
tbuf_handler.set_tbuf_type_mask(get_type_mask());
tbuf_handler.set_tbuf_typemask(get_typemask());
return CMD_NOQUIT;
}
@ -624,7 +747,6 @@ CMD (cmd_tb_dump, cg)
break;
case 'r':
start = get_dec ("From record", 0);
count = get_dec ("Record count", count);
// Fall through
case 't':
count = get_dec ("Record count", count);
@ -694,7 +816,7 @@ DECLARE_CMD (cmd_tb_events, tracebuf, 'F', "filter", "Record display filter");
CMD (cmd_tb_events, cg)
{
tbuf_handler.set_typemask(get_type_mask());
tbuf_handler.set_typemask(get_typemask());
return CMD_NOQUIT;
}
@ -720,6 +842,8 @@ CMD(cmd_tb_evt, cg)
return CMD_NOQUIT;
else if (id <= tp_list.size ())
tbuf_handler.set_id(i, id);
else if (id >= TB_USERID_START)
tbuf_handler.set_id(i, id);
break;
}
if (get_choice ("More events", "y/n", 'n') == 'n')

View File

@ -41,15 +41,8 @@
#include INC_API(smp.h)
#define DEBUG_IRQ
#if defined(DEBUG_IRQ)
DECLARE_TRACEPOINT(INTERRUPT_DETAILS);
#define TRACE_IRQ_DETAILS(x...) TRACEPOINT(INTERRUPT_DETAILS, x);
#else
#define TRACE_IRQ_DETAILS(x...)
#endif
DECLARE_TRACEPOINT(INTERRUPT);
DECLARE_TRACEPOINT_DETAIL(INTERRUPT_DETAILS);
DECLARE_TRACEPOINT(SYSCALL_THREAD_CONTROL_IRQ);
static utcb_t *irq_utcb;

View File

@ -44,13 +44,13 @@
DECLARE_TRACEPOINT(SYSCALL_IPC);
DECLARE_TRACEPOINT(IPC_TRANSFER);
DECLARE_TRACEPOINT_DETAIL(IPC_TRANSFER);
DECLARE_TRACEPOINT_DETAIL(IPC_DETAILS);
DECLARE_TRACEPOINT_DETAIL(IPC_ERROR);
DECLARE_TRACEPOINT_DETAIL(IPC_XCPU_DETAILS);
INLINE bool transfer_message(tcb_t * src, tcb_t * dst, msg_tag_t tag)
{
ASSERT(src);
@ -127,7 +127,7 @@ static void do_xcpu_receive(cpu_mb_entry_t * entry)
tcb_t * from_tcb = entry->tcb;
tcb_t * to_tcb = (tcb_t*)entry->param[0];
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu %s from_tcb: %t (s=%s) to_tcb: %t (s=%s)",
TRACE_XIPC_DETAILS("ipc xcpu %s from_tcb: %t (s=%s) to_tcb: %t (s=%s)",
__func__, from_tcb, from_tcb->get_state().string(),
to_tcb, to_tcb->get_state().string());
@ -152,14 +152,14 @@ static void do_xcpu_send_reply(cpu_mb_entry_t * entry)
{
// the send operation can start now
tcb_t * from_tcb = (tcb_t*)entry->tcb;
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu %s current %t from_tcb: %t (s=%s), result %x",
TRACE_XIPC_DETAILS("ipc xcpu %s current %t from_tcb: %t (s=%s), result %x",
__func__, get_current_tcb(), entry->tcb, entry->tcb->get_state().string(),
entry->param[0]);
// we can let the thread run
if (!from_tcb->is_local_cpu())
{
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu %s from_tcb: %t (%s) migrated to cpu %d",
TRACE_XIPC_DETAILS("ipc xcpu %s from_tcb: %t (%s) migrated to cpu %d",
__func__, entry->tcb, entry->tcb->get_state().string(), from_tcb->get_cpu());
// Forward request
@ -185,14 +185,14 @@ static void do_xcpu_send(cpu_mb_entry_t * entry)
ASSERT(to_tcb);
ASSERT(from_tcb);
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu %s to_tcb: %t (%s), from_tcb: %t (%s)",
TRACE_XIPC_DETAILS("ipc xcpu %s to_tcb: %t (%s), from_tcb: %t (%s)",
__func__, to_tcb, to_tcb->get_state().string(),
from_tcb, from_tcb->get_state().string());
// did the receiver migrate meanwhile?
if (!to_tcb->is_local_cpu())
{
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu %s to_tcb: %t migrated to cpu %d",
TRACE_XIPC_DETAILS("ipc xcpu %s to_tcb: %t migrated to cpu %d",
__func__, to_tcb, to_tcb->get_cpu());
xcpu_request(from_tcb->get_cpu(), do_xcpu_send_reply, from_tcb, 1);
return;
@ -215,13 +215,13 @@ static void do_xcpu_send(cpu_mb_entry_t * entry)
{
// ok, we are locked_waiting -- means we already issued
// a request packet (do_xcpu_receive) -- so don't bother
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu %s %t is locked_waiting for %t",
TRACE_XIPC_DETAILS("ipc xcpu %s %t is locked_waiting for %t",
__func__, to_tcb, TID(sender_id));
enter_kdebug("UNTESTED");
}
else
{
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu %s (not waiting) to_tcb: %t (%s), from_tcb: %t",
TRACE_XIPC_DETAILS("ipc xcpu %s (not waiting) to_tcb: %t (%s), from_tcb: %t",
__func__, to_tcb, to_tcb->get_state().string(), from_tcb);
xcpu_request(from_tcb->get_cpu(), do_xcpu_send_reply, from_tcb, 1);
}
@ -233,13 +233,13 @@ static void do_xcpu_send_done(cpu_mb_entry_t * entry)
threadid_t sender_id;
sender_id.set_raw(entry->param[0]);
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu %s to_tcb: %t (%s)",
TRACE_XIPC_DETAILS("ipc xcpu %s to_tcb: %t (%s)",
__func__, to_tcb, to_tcb->get_state().string());
// did the receiver migrate meanwhile?
if (!to_tcb->is_local_cpu())
{
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu %s to_tcb: %t migrated to cpu %d",
TRACE_XIPC_DETAILS("ipc xcpu %s to_tcb: %t migrated to cpu %d",
__func__, to_tcb, to_tcb->get_cpu());
// Forward request
xcpu_request( to_tcb->get_cpu(), do_xcpu_send_done, to_tcb, sender_id.get_raw());
@ -297,12 +297,12 @@ send_path:
{
#warning add local id handling
to_tcb = current->get_space()->get_tcb(to_tid);
TRACEPOINT(IPC_DETAILS, "ipc send phase curr=%t, to=%t", current, TID(to_tid));
TRACE_IPC_DETAILS("ipc send phase curr=%t, to=%t", current, TID(to_tid));
if (EXPECT_FALSE( to_tcb->get_global_id() != to_tid ))
{
/* specified thread id invalid */
TRACEPOINT(IPC_ERROR, "ipc invalid send tid, wanted %t, but have %t", to_tid.get_raw(), to_tcb);
TRACE_IPC_ERROR("ipc invalid send tid, wanted %t, but have %t", to_tid.get_raw(), to_tcb);
current->set_error_code(IPC_SND_ERROR(ERR_IPC_NON_EXISTING));
current->set_tag(msg_tag_t::error_tag());
return_ipc(NILTHREAD);
@ -352,7 +352,7 @@ send_path:
// Not waiting for actual sender (if propagating IPC)?
to_tcb->get_partner() != current->get_global_id() )))
{
TRACEPOINT(IPC_DETAILS, "ipc blocking send (curr=%t, to=%t s=%s)",
TRACE_IPC_DETAILS("ipc blocking send (curr=%t, to=%t s=%s)",
current, TID(to_tid), to_tcb->get_state().string());
//enter_kdebug("blocking send");
@ -361,7 +361,7 @@ send_path:
{
if (timeout.get_snd().is_zero())
{
TRACEPOINT(IPC_ERROR, "ipc zero send timeout (curr=%t, to=%t)", current, TID(to_tid));
TRACE_IPC_ERROR("ipc zero send timeout (curr=%t, to=%t)", current, TID(to_tid));
/* VU: set thread state to running - in case we
* had a long IPC. Not on the critical path */
current->set_state(thread_state_t::running);
@ -370,7 +370,7 @@ send_path:
to_tcb->unlock();
return_ipc(NILTHREAD);
}
TRACEPOINT(IPC_DETAILS, "ipc setting timeout %dus", timeout.get_snd().get_microseconds());
TRACE_IPC_DETAILS("ipc setting timeout %dus", timeout.get_snd().get_microseconds());
scheduler->set_timeout(current, timeout.get_snd());
}
#ifdef CONFIG_SMP
@ -395,7 +395,7 @@ send_path:
else if (EXPECT_FALSE( !to_tcb->is_local_cpu() && !to_tcb->lock_state.is_enabled() ))
{
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu send %t:%d (%s) -> %t:%d (%s)",
TRACE_XIPC_DETAILS("ipc xcpu send %t:%d (%s) -> %t:%d (%s)",
current, current->get_cpu(), current->get_state().string(),
to_tcb, to_tcb->get_cpu(), to_tcb->get_state().string());
@ -407,7 +407,7 @@ send_path:
current->switch_to_idle();
// re-activated?
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu got reactivated after waiting to send %t:%d (%s) -> %t:%d (%s) result %d",
TRACE_XIPC_DETAILS("ipc xcpu got reactivated after waiting to send %t:%d (%s) -> %t:%d (%s) result %d",
current, current->get_cpu(), current->get_state().string(),
to_tcb, to_tcb->get_cpu(), to_tcb->get_state().string(), current->xcpu_status);
@ -426,7 +426,7 @@ send_path:
return_ipc(NILTHREAD);
}
#endif
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu send failed, retry to send %t:%d (%s) -> %t:%d (%s)",
TRACE_XIPC_DETAILS("ipc xcpu send failed, retry to send %t:%d (%s) -> %t:%d (%s)",
current, current->get_cpu(), current->get_state().string(),
to_tcb, to_tcb->get_cpu(), to_tcb->get_state().string());
@ -480,7 +480,7 @@ send_path:
/* VU: kick receiver and forget about him
* we have to transmit the sender id since it is
* going to change in the receive path!!! */
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu notify on send done %t:%d (%s) -> %t:%d (%s)",
TRACE_XIPC_DETAILS("ipc xcpu notify on send done %t:%d (%s) -> %t:%d (%s)",
current, current->get_cpu(), current->get_state().string(),
to_tcb, to_tcb->get_cpu(), to_tcb->get_state().string());
@ -498,7 +498,7 @@ send_path:
}
/* --- send finished ------------------------------------------------ */
TRACEPOINT(IPC_DETAILS, "ipc send finished curr=%t to=%t from_tid %x", current, to_tcb, TID(from_tid));
TRACE_IPC_DETAILS("ipc send finished curr=%t to=%t from_tid %x", current, to_tcb, TID(from_tid));
if (EXPECT_FALSE( from_tid.is_nilthread() ))
{
@ -534,7 +534,7 @@ send_path:
/* --- receive phase ------------------------------------------------ */
else /* ! from_tid.is_nilthread() */
{
TRACEPOINT(IPC_DETAILS, "ipc receive phase curr=%t, from=%t", current, TID(from_tid));
TRACE_IPC_DETAILS("ipc receive phase curr=%t, from=%t", current, TID(from_tid));
#if defined(CONFIG_SMP)
/* VU: set thread state early to catch races */
@ -556,14 +556,14 @@ send_path:
from_tcb = current->get_space()->get_tcb(from_tid);
TRACEPOINT(IPC_DETAILS, "ipc closed wait from %t, current=%t", TID(from_tid), current);
TRACE_IPC_DETAILS("ipc closed wait from %t, current=%t", TID(from_tid), current);
if (EXPECT_FALSE( (from_tcb->get_global_id() != from_tid) &&
( (from_tcb->get_space() != current->get_space()) ||
(from_tcb->get_local_id() != from_tid) ) ))
{
/* wrong receiver id */
TRACEPOINT(IPC_ERROR, "ipc invalid receiver id (curr=%t, from=%t)", current, TID(from_tid));
TRACE_IPC_ERROR("ipc invalid receiver id (curr=%t, from=%t)", current, TID(from_tid));
current->set_tag(msg_tag_t::error_tag());
current->set_error_code(IPC_RCV_ERROR(ERR_IPC_NON_EXISTING));
ON_CONFIG_SMP(current->set_state(thread_state_t::running));
@ -605,7 +605,7 @@ send_path:
( (from_tcb->get_partner() != current->get_global_id()) &&
(from_tcb->get_partner() != current->myself_local) )) )
{
TRACEPOINT(IPC_DETAILS, "ipc blocking receive (curr=%t, from=%t)", current, TID(from_tid));
TRACE_IPC_DETAILS("ipc blocking receive (curr=%t, from=%t)", current, TID(from_tid));
/* partner is not trying to send to me */
if (EXPECT_FALSE( !timeout.get_rcv().is_never() ))
@ -615,7 +615,7 @@ send_path:
if ( timeout.get_rcv().is_zero() )
{
TRACEPOINT(IPC_ERROR, "ipc receive error (curr=%t, from=%t)", current, TID(from_tid));
TRACE_IPC_ERROR("ipc receive error (curr=%t, from=%t)", current, TID(from_tid));
current->set_tag(msg_tag_t::error_tag());
current->set_state(thread_state_t::running);
current->unlock();
@ -628,7 +628,7 @@ send_path:
}
return_ipc(NILTHREAD);
}
TRACEPOINT(IPC_DETAILS, "ipc setting timeout %dus", timeout.get_rcv().get_microseconds());
TRACE_IPC_DETAILS("ipc setting timeout %dus", timeout.get_rcv().get_microseconds());
scheduler->set_timeout(current, timeout.get_rcv());
current->set_state(thread_state_t::waiting_timeout);
}
@ -656,7 +656,7 @@ send_path:
* return from the IPC without additional checking
* here. */
TRACEPOINT(IPC_DETAILS, "ipc %t received msg from %t (virtual %t)", current, current->get_partner_tcb());
TRACE_IPC_DETAILS("ipc %t received msg from %t (virtual %t)", current, current->get_partner_tcb());
/* XXX VU: restructure switching code so that dequeueing
* from wakeup is removed from critical path */
@ -664,7 +664,7 @@ send_path:
}
else
{
TRACEPOINT(IPC_DETAILS, "ipc perform receive from %t", from_tcb);
TRACE_IPC_DETAILS("ipc perform receive from %t", from_tcb);
//enter_kdebug("do receive");
// both threads on the same CPU?
@ -703,7 +703,7 @@ send_path:
#if defined(CONFIG_SMP)
else
{
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu receive curr=%t:%d -> from=%t:%d",
TRACE_XIPC_DETAILS("ipc xcpu receive curr=%t:%d -> from=%t:%d",
current, current->get_cpu(), from_tcb, from_tcb->get_cpu());
current->set_state(thread_state_t::locked_waiting);
@ -722,7 +722,7 @@ send_path:
if (!to_tcb) to_tcb = get_idle_tcb();
current->switch_to(to_tcb);
TRACEPOINT(IPC_XCPU_DETAILS, "ipc xcpu receive done (from=%t, curr=%t)\n", from_tcb, current);
TRACE_XIPC_DETAILS("ipc xcpu receive done (from=%t, curr=%t)\n", from_tcb, current);
}
#endif
}

View File

@ -41,11 +41,11 @@
#define CHECK_MR_IDX(idx, total) if (idx > total) goto message_overflow
DECLARE_TRACEPOINT(IPC_STRING_COPY);
DECLARE_TRACEPOINT(IPC_STRING_ITEM);
DECLARE_TRACEPOINT(IPC_MAPGRANT_ITEM);
DECLARE_TRACEPOINT(IPC_MESSAGE_OVERFLOW);
DECLARE_TRACEPOINT(IPC_EXT_TRANSFER);
DECLARE_TRACEPOINT_DETAIL(IPC_STRING_COPY);
DECLARE_TRACEPOINT_DETAIL(IPC_STRING_ITEM);
DECLARE_TRACEPOINT_DETAIL(IPC_MAPGRANT_ITEM);
DECLARE_TRACEPOINT_DETAIL(IPC_MESSAGE_OVERFLOW);
DECLARE_TRACEPOINT_DETAIL(IPC_EXT_TRANSFER);
#if !defined(IPC_STRING_COPY)
extern "C" void * memcpy (void * dst, const void * src, word_t len);

View File

@ -1,6 +1,6 @@
/*********************************************************************
*
* Copyright (C) 2002-2004, 2006-2007, Karlsruhe University
* Copyright (C) 2002-2004, 2006-2008, Karlsruhe University
*
* File path: api/v4/schedule.cc
* Description: Scheduling functions
@ -62,9 +62,7 @@ DECLARE_TRACEPOINT(PREEMPTION_DELAY_REFRESH);
DECLARE_TRACEPOINT(WAKEUP_TIMEOUT);
DECLARE_TRACEPOINT(SYSCALL_SCHEDULE);
#if defined(DEBUG_SCHEDULE)
DECLARE_TRACEPOINT(SCHEDULE_DETAILS);
#endif
DECLARE_TRACEPOINT_DETAIL(SCHEDULE_DETAILS);
#ifdef CONFIG_SMP

View File

@ -1,6 +1,6 @@
/*********************************************************************
*
* Copyright (C) 2002-2004, 2007, Karlsruhe University
* Copyright (C) 2002-2004, 2007-2008, Karlsruhe University
*
* File path: api/v4/schedule.h
* Description: scheduling declarations
@ -38,13 +38,7 @@
#include <kdb/tracepoints.h>
#define DEBUG_SCHEDULE
#if defined(DEBUG_SCHEDULE)
EXTERN_TRACEPOINT(SCHEDULE_DETAILS);
#define TRACE_SCHEDULE_DETAILS(x...) TRACEPOINT(SCHEDULE_DETAILS, x);
#else
#define TRACE_SCHEDULE_DETAILS(x...)
#endif
class prio_queue_t
{

View File

@ -116,11 +116,11 @@ INLINE tracebuffer_t * get_tracebuffer (void)
* Access to performance monitoring counters
*/
#if defined(CONFIG_TBUF_PERFMON)
#if defined(CONFIG_TBUF_PERFMON)
# if defined(CONFIG_CPU_X86_I686) || defined(CONFIG_CPU_X86_K8) || defined(CONFIG_CPU_X86_K8)
# define TBUF_PMC_SEL_0 " xor %1, %1 \n"
# define TBUF_PMC_SEL_1 " inc %1 \n"
# define TBUF_PMC_SEL_1 " mov $1, %1 \n"
# elif defined(CONFIG_CPU_X86_P4)
/* PMC_MSR_IQ_COUNTER 0 and 2 */
# define TBUF_PMC_SEL_0 " mov $12, %1 \n"
@ -155,7 +155,6 @@ INLINE tracebuffer_t * get_tracebuffer (void)
*
* @returns index to current event record
*/
#define TBUF_GET_NEXT_RECORD(type, id) \
({ \
word_t dummy, addr; \
@ -185,12 +184,12 @@ INLINE tracebuffer_t * get_tracebuffer (void)
" lea __idle_tcb, %3 \n" \
" movw "MKSTR(OFS_TCB_CPU)"(%3), %%dx \n" \
" movl %%edx, %%fs:1*%c9(%0) \n" \
TBUF_RDTSC \
TBUF_SP \
TBUF_PMC_SEL_0 \
TBUF_RDPMC_0 \
TBUF_PMC_SEL_1 \
TBUF_RDPMC_1 \
TBUF_RDTSC \
TBUF_SP \
"2: \n" \
: \
"=D" (addr), /* 0 */ \

View File

@ -33,23 +33,39 @@
#include <tcb_layout.h>
#define TRACEBUFFER_MAGIC 0x143acebf
#define TRACEBUFFER_PGENTSZ pgent_t::size_4m
/*
* Access to stack pointer, timestamp, and performance monitoring counters
*/
#define TBUF_RDTSC " rdtsc \n" \
" mov %%eax, %%fs:2*%c9(%0) \n"
#define TBUF_SP " mov %%esp, %%fs:3*%c9(%0) \n" \
#if defined(CONFIG_TBUF_PERFMON)
#define TBUF_RDPMC_0 " rdpmc \n" \
/* Registers:
* EAX unused
* EBX unused, not preserved
* ECX unused
* EDX unused
* ESI unused, not preserved
* EDI TB record address
* EBP unused, not preserved
*/
#define TBUF_RDPMC_0 " rdpmc \n" \
" movl %%eax, %%fs:4*%c9(%0) \n"
#define TBUF_RDPMC_1 " rdpmc \n" \
#define TBUF_RDPMC_1 " rdpmc \n" \
" movl %%eax, %%fs:5*%c9(%0) \n"
#endif
#endif /* CONFIG_TBUF_PERFMON */
#define TBUF_RDTSC " rdtsc \n" \
" mov %%eax, %%fs:2*%c9(%0) \n"
#endif /* !__ARCH__X86__X32__TRACEBUFFER_H__ */

View File

@ -1,6 +1,6 @@
/*********************************************************************
*
* Copyright (C) 2007, Karlsruhe University
* Copyright (C) 2007-2008, Karlsruhe University
*
* File path: glue/v4-x86/exception.cc
* Description:
@ -21,7 +21,7 @@
#include INC_API(kernelinterface.h)
#include INC_GLUE(traphandler.h)
DECLARE_TRACEPOINT (EXCEPTION_IPC);
DECLARE_TRACEPOINT_DETAIL (EXCEPTION_IPC);
DECLARE_TRACEPOINT (X86_NOMATH);
DECLARE_TRACEPOINT (X86_GP);
DECLARE_TRACEPOINT (X86_SEGRELOAD);

View File

@ -32,14 +32,17 @@
#ifndef __KDB__TRACEBUFFER_H__
#define __KDB__TRACEBUFFER_H__
#if defined(CONFIG_TRACEBUFFER)
#define TB_DEFAULT (1 << 0)
#define TB_USERID_START (100)
/*
* Wrap tracepoint events with event type arguments
*/
extern void tbuf_dump (word_t count, word_t usec, word_t tp_id = 0, word_t cpumask=~0UL);
#define DEBUG_KERNEL_DETAILS
#if defined(DEBUG_KERNEL_DETAILS)

View File

@ -36,8 +36,14 @@
#include <kdb/linker_set.h>
#include <kdb/tracebuffer.h>
#define TP_DEFAULT (1 << 1)
#define TP_DETAIL (1 << 2)
#define TP_DEFAULT (1 << 0)
#define TP_DETAIL (1 << 1)
#define TRACE_SCHEDULE_DETAILS(x...) TRACEPOINT(SCHEDULE_DETAILS, x)
#define TRACE_IPC_DETAILS(x...) TRACEPOINT(IPC_DETAILS, x)
#define TRACE_XIPC_DETAILS(x...) TRACEPOINT(IPC_XCPU_DETAILS, x)
#define TRACE_IPC_ERROR(x...) TRACEPOINT(IPC_ERROR, x)
#define TRACE_IRQ_DETAILS(x...) TRACEPOINT(INTERRUPT_DETAILS, x)
// avoid including api/smp.h for non-SMP case
#if !defined(CONFIG_SMP)
@ -104,6 +110,7 @@ extern tracepoint_list_t tp_list;
tracepoint_t __tracepoint_##tp = { #tp, 0, TP_DETAIL, 0, 0, { 0, } }; \
PUT_SET (tracepoint_set, __tracepoint_##tp)
#define TRACEPOINT(tp, str, args...) \
do { \
tracepoint_t *_tp = &__tracepoint_##tp; \
@ -113,9 +120,9 @@ do { \
{ \
{ printf("tcb %t cpu %d: ", TP_TCB, TP_CPU); \
printf(str, ##args); printf("\n");} \
if (_tp->enter_kdb & (1UL << TP_CPU)) \
enter_kdebug (#tp); \
} \
if (_tp->enter_kdb & (1UL << TP_CPU)) \
enter_kdebug (#tp); \
} while (0)
@ -126,9 +133,10 @@ do { \
if (tp->enabled & (1UL << TP_CPU)) \
{ \
{code;} \
if (tp->enter_kdb & (1UL << TP_CPU)) \
enter_kdebug (#tp); \
} \
if (tp->enter_kdb & (1UL << TP_CPU)) \
enter_kdebug (#tp); \
\
} while (0)
#define ENABLE_TRACEPOINT(tp, cpumask, kdbmask) \

View File

@ -32,49 +32,17 @@
#include <l4/types.h>
#if !defined(__L4__AMD64__TRACEBUFFER_H__)
/*
* Access to stack pointer, timestamp, and performance monitoring counters
*/
#define __L4_TBUF_RDTSC " rdtsc \n" \
" mov %3, %%fs:2*%c9(%0) \n"
#if defined(L4_PERFMON)
# define __L4_TBUF_RDPMC_0 " rdpmc \n" \
" mov %3, %%fs:4*%c9(%0) \n"
# define __L4_TBUF_RDPMC_1 " rdpmc \n" \
" mov %3, %%fs:5*%c9(%0) \n"
# if !defined(L4_CONFIG_CPU_IA32_P4)
# define __L4_TBUF_PMC_SEL_0 " xorl %%ecx, %%ecx \n"
# define __L4_TBUF_PMC_SEL_1 " inc %%ecx \n"
# elif defined(L4_CONFIG_CPU_IA32_P4)
# define __L4_TBUF_PMC_SEL_0 " movl $12, %%ecx \n"
# define __L4_TBUF_PMC_SEL_1 " addl $2, %%ecx \n"
# endif
#else /* L4_PERFMON */
# define __L4_TBUF_PMC_SEL_0
# define __L4_TBUF_PMC_SEL_1
# define __L4_TBUF_RDPMC_0
# define __L4_TBUF_RDPMC_1
#endif /* L4_PERFMON */
# define __PLUS32
#endif /* !defined(__L4__AMD64__TRACEBUFFER_H__) */
/* Turn preprocessor symbol definition into string */
#define MKSTR(sym) MKSTR2(sym)
#define MKSTR2(sym) #sym
#if defined(L4_64BIT)
# define __PLUS32 + 32
#else
# define __PLUS32
#endif
#define L4_TRACEBUFFER_MAGIC (0x143acebf)
#define L4_TRACEBUFFER_NUM_ARGS (9)
@ -101,7 +69,43 @@ typedef struct
} L4_TraceRecord_t;
/*
* Access to performance monitoring counters
*/
#if defined(L4_PERFMON)
# define __L4_TBUF_RDPMC_0 " rdpmc \n" \
" mov %3, %%fs:4*%c9(%0) \n"
# define __L4_TBUF_RDPMC_1 " rdpmc \n" \
" mov %3, %%fs:5*%c9(%0) \n"
#if defined(L4_CONFIG_CPU_X86_P4)
# define __L4_TBUF_PMC_SEL_0 " movl $12, %%ecx \n"
# define __L4_TBUF_PMC_SEL_1 " addl $2, %%ecx \n"
#elif defined(L4_CONFIG_CPU_X86_K8)
# define __L4_TBUF_PMC_SEL_0 " xorl %%ecx, %%ecx \n"
# define __L4_TBUF_PMC_SEL_1 " inc %%ecx \n"
#else
# error define CPU type for energy tracing
#endif
#else /* L4_PERFMON */
# define __L4_TBUF_PMC_SEL_0
# define __L4_TBUF_PMC_SEL_1
# define __L4_TBUF_RDPMC_0
# define __L4_TBUF_RDPMC_1
#endif /* L4_PERFMON */
#if !defined(L4_PERFMON_ENERGY)
#define __L4_TBUF_RDTSC " rdtsc \n" \
" mov %3, %%fs:2*%c9(%0) \n"
#endif
/*
* Make sure cmpxchg is atomic
*/
@ -144,7 +148,6 @@ do { \
" mov %8, %0 \n" \
" mov %0, %2 \n" \
" add %3, %0 \n" \
" mov %%fs:3*%c9, %2 \n" \
" and %%fs:3*%c9, %0 \n" \
" cmovz %2, %0 \n" \
__L4_TBUF_LOCK \
@ -161,11 +164,11 @@ do { \
" movl %%edx, %%fs:1*%c9(%0) \n" \
" mov "MKSTR(__L4_TCR_MY_GLOBAL_ID)"*%c9(%1), %2\n" \
" mov %2, %%fs:3*%c9(%0) \n" \
__L4_TBUF_RDTSC \
__L4_TBUF_PMC_SEL_0 \
__L4_TBUF_RDPMC_0 \
__L4_TBUF_PMC_SEL_1 \
__L4_TBUF_RDPMC_1 \
__L4_TBUF_RDTSC \
"2: \n" \
: \
"=D" (_addr), /* 0 */ \