Syscall tracing
authorBarret Rhoden <brho@cs.berkeley.edu>
Tue, 27 Apr 2010 01:57:51 +0000 (18:57 -0700)
committerKevin Klues <klueska@cs.berkeley.edu>
Thu, 3 Nov 2011 00:35:45 +0000 (17:35 -0700)
Turn it on in the monitor, or however.  The monitor defaults are loud
(prints as they happen) and for all processes.  Pass anything other than
0 for silent (treated as a bool).  Currently only traces 1024 events, so
quit making vcoreid calls.

kern/include/monitor.h
kern/include/syscall.h
kern/src/monitor.c
kern/src/syscall.c

index a55b26d..74ed0ba 100644 (file)
@@ -27,5 +27,7 @@ int mon_procinfo(int argc, char *NTS *NT COUNT(argc) argv, trapframe_t *tf);
 int mon_exit(int argc, char *NTS *NT COUNT(argc) argv, trapframe_t *tf);
 int mon_kfunc(int argc, char *NTS *NT COUNT(argc) argv, trapframe_t *tf);
 int mon_notify(int argc, char *NTS *NT COUNT(argc) argv, trapframe_t *tf);
+int mon_measure(int argc, char *NTS *NT COUNT(argc) argv, trapframe_t *tf);
+int mon_trace(int argc, char *NTS *NT COUNT(argc) argv, trapframe_t *tf);
 
 #endif // !ROS_KERN_MONITOR_H
index ce9f494..03ae2f5 100644 (file)
 #define PTR_ERR(ptr)  ((uintptr_t)(ptr))
 #define IS_ERR(ptr)   ((uintptr_t)-(uintptr_t)(ptr) < 512)
 
+#define SYSTRACE_ON                                    0x01
+#define SYSTRACE_LOUD                          0x02
+#define SYSTRACE_ALLPROC                       0x04
+
+#define MAX_NUM_TRACED                         10
+#define MAX_SYSTRACES                          1024
+
+/* Consider cache aligning this */
+struct systrace_record {
+       uint64_t                timestamp;
+       uintreg_t               syscallno;
+       int                             pid;
+       uint32_t                coreid;
+       uint32_t                vcoreid;
+};
 
 intreg_t syscall(struct proc *p, uintreg_t num, uintreg_t a1, uintreg_t a2,
                  uintreg_t a3, uintreg_t a4, uintreg_t a5);
 intreg_t syscall_async(env_t* e, syscall_req_t *syscall);
 intreg_t process_generic_syscalls(env_t* e, size_t max);
 
+/* Tracing functions */
+void systrace_start(bool silent);
+void systrace_stop(void);
+int systrace_reg(bool all, struct proc *p);
+int systrace_dereg(bool all, struct proc *p);
+void systrace_print(bool all, struct proc *p);
+void systrace_clear_buffer(void);
+
 intreg_t sys_read(struct proc* p, int fd, void* buf, int len);
 intreg_t sys_write(struct proc* p, int fd, const void* buf, int len);
 intreg_t sys_pread(struct proc* p, int fd, void* buf, int len, int offset);
index 5fc8c7e..70ede47 100644 (file)
@@ -23,6 +23,8 @@
 #include <schedule.h>
 #include <resource.h>
 #include <kdebug.h>
+#include <syscall.h>
+#include <kmalloc.h>
 
 #include <ros/memlayout.h>
 
@@ -53,6 +55,8 @@ static command_t (RO commands)[] = {
        { "exit", "Leave the monitor", mon_exit},
        { "kfunc", "Run a kernel function directly (!!!)", mon_kfunc},
        { "notify", "Notify a process.  Vcoreid will skip their prefs", mon_notify},
+       { "measure", "Run a specific measurement", mon_measure},
+       { "trace", "Run a specific measurement", mon_trace},
 };
 #define NCOMMANDS (sizeof(commands)/sizeof(commands[0]))
 
@@ -447,6 +451,80 @@ int mon_notify(int argc, char *NTS *NT COUNT(argc) argv, trapframe_t *tf)
        proc_decref(p, 1);
        return 0;
 }
+
+/* Micro-benchmarky Measurements */
+int mon_measure(int argc, char *NTS *NT COUNT(argc) argv, trapframe_t *tf)
+{
+       if (argc < 2) {
+               printk("Usage: measure OPTION\n");
+               printk("\topt1: whatever\n");
+               return 1;
+       }
+       if (!strcmp(argv[1], "opt1")) {
+               print_idlecoremap();
+       } else if (!strcmp(argv[1], "opt2")) {
+               if (argc != 3) {
+                       printk("ERRRRRRRRRR.\n");
+                       return 1;
+               }
+               print_proc_info(strtol(argv[2], 0, 0));
+       } else {
+               printk("Bad option\n");
+               return 1;
+       }
+       return 0;
+}
+
+int mon_trace(int argc, char *NTS *NT COUNT(argc) argv, trapframe_t *tf)
+{
+       if (argc < 2) {
+               printk("Usage: trace OPTION\n");
+               printk("\tsyscall start [silent] [pid]: starts tracing\n");
+               printk("\tsyscall stop: stops tracing, prints if it was silent\n");
+               return 1;
+       }
+       if (!strcmp(argv[1], "syscall")) {
+               if (argc < 3) {
+                       printk("Need a start or stop.\n");
+                       return 1;
+               }
+               if (!strcmp(argv[2], "start")) {
+                       bool all = TRUE;
+                       bool silent = FALSE;
+                       struct proc *p = NULL;
+                       if (argc >= 4) {
+                               silent = (bool)strtol(argv[3], 0, 0);
+                       }
+                       if (argc >= 5) {
+                               all = FALSE;
+                               p = pid2proc(strtol(argv[4], 0, 0));
+                               if (!p) {
+                                       printk("No such process\n");
+                                       return 1;
+                               }
+                       }
+                       systrace_start(silent);
+                       if (systrace_reg(all, p))
+                               printk("No room to trace more processes\n");
+               } else if (!strcmp(argv[2], "stop")) {
+                       /* Stop and print for all processes */
+                       systrace_stop();
+                       systrace_print(TRUE, 0);
+                       systrace_clear_buffer();
+               }
+       } else if (!strcmp(argv[1], "opt2")) {
+               if (argc != 3) {
+                       printk("ERRRRRRRRRR.\n");
+                       return 1;
+               }
+               print_proc_info(strtol(argv[2], 0, 0));
+       } else {
+               printk("Bad option\n");
+               return 1;
+       }
+       return 0;
+}
+
 /***** Kernel monitor command interpreter *****/
 
 #define WHITESPACE "\t\r\n "
index ead2509..0749a54 100644 (file)
@@ -37,6 +37,23 @@ extern int (*send_frame)(const char *CT(len) data, size_t len);
 extern unsigned char device_mac[6];
 #endif
 
+/* Tracing Globals */
+int systrace_flags = 0;
+struct systrace_record *systrace_buffer = 0;
+unsigned int systrace_bufidx = 0;
+size_t systrace_bufsize = 0;
+struct proc *systrace_procs[MAX_NUM_TRACED] = {0};
+spinlock_t systrace_lock = SPINLOCK_INITIALIZER;
+
+/* Not enforcing the packing of systrace_procs yet, but don't rely on that */
+static bool proc_is_traced(struct proc *p)
+{
+       for (int i = 0; i < MAX_NUM_TRACED; i++)
+               if (systrace_procs[i] == p)
+                       return true;
+       return false;
+}
+
 /************** Utility Syscalls **************/
 
 static int sys_null(void)
@@ -1137,6 +1154,30 @@ intreg_t syscall(struct proc *p, uintreg_t syscallno, uintreg_t a1,
 
        const int max_syscall = sizeof(syscall_table)/sizeof(syscall_table[0]);
 
+       uint32_t coreid, vcoreid;
+       if (systrace_flags & SYSTRACE_ON) {
+               if ((systrace_flags & SYSTRACE_ALLPROC) || (proc_is_traced(p))) {
+                       coreid = core_id();
+                       vcoreid = proc_get_vcoreid(p, core_id());
+                       if (systrace_flags & SYSTRACE_LOUD) {
+                               printk("[%16llu] Syscall %d for proc %d on core %d, vcore %d\n",
+                                      read_tsc(), syscallno, p->pid, coreid, vcoreid);
+                       } else {
+                               struct systrace_record *trace;
+                               unsigned int idx, new_idx;
+                               do {
+                                       idx = systrace_bufidx;
+                                       new_idx = (idx + 1) % systrace_bufsize;
+                               } while (!atomic_comp_swap(&systrace_bufidx, idx, new_idx));
+                               trace = &systrace_buffer[idx];
+                               trace->timestamp = read_tsc();
+                               trace->syscallno = syscallno;
+                               trace->pid = p->pid;
+                               trace->coreid = coreid;
+                               trace->vcoreid = vcoreid;
+                       }
+               }
+       }
        //printk("Incoming syscall on core: %d number: %d\n    a1: %x\n   "
        //       " a2: %x\n    a3: %x\n    a4: %x\n    a5: %x\n", core_id(),
        //       syscallno, a1, a2, a3, a4, a5);
@@ -1199,3 +1240,102 @@ intreg_t process_generic_syscalls(struct proc *p, size_t max)
        return (intreg_t)count;
 }
 
+/* Syscall tracing */
+static void __init_systrace(void)
+{
+       systrace_buffer = kmalloc(MAX_SYSTRACES*sizeof(struct systrace_record), 0);
+       if (!systrace_buffer)
+               panic("Unable to alloc a trace buffer\n");
+       systrace_bufidx = 0;
+       systrace_bufsize = MAX_SYSTRACES;
+       /* Note we never free the buffer - it's around forever.  Feel free to change
+        * this if you want to change the size or something dynamically. */
+}
+
+/* If you call this while it is running, it will change the mode */
+void systrace_start(bool silent)
+{
+       static bool init = FALSE;
+       spin_lock_irqsave(&systrace_lock);
+       if (!init) {
+               __init_systrace();
+               init = TRUE;
+       }
+       systrace_flags = silent ? SYSTRACE_ON : SYSTRACE_ON | SYSTRACE_LOUD; 
+       spin_unlock_irqsave(&systrace_lock);
+}
+
+int systrace_reg(bool all, struct proc *p)
+{
+       int retval = 0;
+       spin_lock_irqsave(&systrace_lock);
+       if (all) {
+               printk("Tracing syscalls for all processes\n");
+               systrace_flags |= SYSTRACE_ALLPROC;
+               retval = 0;
+       } else {
+               for (int i = 0; i < MAX_NUM_TRACED; i++) {
+                       if (!systrace_procs[i]) {
+                               printk("Tracing syscalls for process %d\n", p->pid);
+                               systrace_procs[i] = p;
+                               retval = 0;
+                               break;
+                       }
+               }
+       }
+       spin_unlock_irqsave(&systrace_lock);
+       return retval;
+}
+
+void systrace_stop(void)
+{
+       spin_lock_irqsave(&systrace_lock);
+       systrace_flags = 0;
+       for (int i = 0; i < MAX_NUM_TRACED; i++)
+               systrace_procs[i] = 0;
+       spin_unlock_irqsave(&systrace_lock);
+}
+
+/* If you registered a process specifically, then you need to dereg it
+ * specifically.  Or just fully stop, which will do it for all. */
+int systrace_dereg(bool all, struct proc *p)
+{
+       spin_lock_irqsave(&systrace_lock);
+       if (all) {
+               printk("No longer tracing syscalls for all processes.\n");
+               systrace_flags &= ~SYSTRACE_ALLPROC;
+       } else {
+               for (int i = 0; i < MAX_NUM_TRACED; i++) {
+                       if (systrace_procs[i] == p) {
+                               systrace_procs[i] = 0;
+                               printk("No longer tracing syscalls for process %d\n", p->pid);
+                       }
+               }
+       }
+       spin_unlock_irqsave(&systrace_lock);
+       return 0;
+}
+
+/* Regardless of locking, someone could be writing into the buffer */
+void systrace_print(bool all, struct proc *p)
+{
+       spin_lock_irqsave(&systrace_lock);
+       /* if you want to be clever, you could make this start from the earliest
+        * timestamp and loop around.  Careful of concurrent writes. */
+       for (int i = 0; i < systrace_bufsize; i++)
+               if (systrace_buffer[i].timestamp)
+                       printk("[%16llu] Syscall %d for proc %d on core %d, vcore %d\n",
+                              systrace_buffer[i].timestamp,
+                              systrace_buffer[i].syscallno,
+                              systrace_buffer[i].pid,
+                              systrace_buffer[i].coreid,
+                              systrace_buffer[i].vcoreid);
+       spin_unlock_irqsave(&systrace_lock);
+}
+
+void systrace_clear_buffer(void)
+{
+       spin_lock_irqsave(&systrace_lock);
+       memset(systrace_buffer, 0, sizeof(struct systrace_record)*MAX_NUM_TRACED);
+       spin_unlock_irqsave(&systrace_lock);
+}