1 files changed, 47 insertions, 189 deletions

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 6ec4f51d536b..de93a2604528 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -61,29 +61,6 @@ static u64			sample_type;
 
 typedef unsigned long long nsec_t;
 
-#define printk(x...)            do { printf(x); fflush(stdout); } while (0)
-
-nsec_t prev_printk;
-
-#define __dprintk(x,y...) do {                                           \
-        nsec_t __now = get_nsecs(), __delta = __now - prev_printk;       \
-                                                                         \
-        prev_printk = __now;                                             \
-                                                                         \
-        printf("%.3f [%Ld] [%.3f]: " x, (double)__now/1e6, __now, (double)__delta/1e6, y);\
-} while (0)
-
-#if !DEBUG
-# define dprintk(x...)  do { } while (0)
-#else
-# define dprintk(x...)  __dprintk(x)
-#endif
-
-#define __DP()          __dprintk("parent: line %d\n", __LINE__)
-#define DP()            dprintk("parent: line %d\n", __LINE__)
-#define D()             dprintk("task %ld: line %d\n", this_task->nr, __LINE__)
-
-
 static nsec_t run_measurement_overhead;
 static nsec_t sleep_measurement_overhead;
 
@@ -129,7 +106,7 @@ static void calibrate_run_measurement_overhead(void)
         }
         run_measurement_overhead = min_delta;
 
-        printk("run measurement overhead: %Ld nsecs\n", min_delta);
+        printf("run measurement overhead: %Ld nsecs\n", min_delta);
 }
 
 static void calibrate_sleep_measurement_overhead(void)
@@ -147,7 +124,7 @@ static void calibrate_sleep_measurement_overhead(void)
         min_delta -= 10000;
         sleep_measurement_overhead = min_delta;
 
-        printk("sleep measurement overhead: %Ld nsecs\n", min_delta);
+        printf("sleep measurement overhead: %Ld nsecs\n", min_delta);
 }
 
 #define COMM_LEN        20
@@ -293,7 +270,7 @@ add_sched_event_wakeup(struct task_desc *task, nsec_t timestamp,
 
 static void
 add_sched_event_sleep(struct task_desc *task, nsec_t timestamp,
-                      unsigned long uninterruptible __used)
+                      u64 task_state __used)
 {
         struct sched_event *event = get_new_event(task, timestamp);
 
@@ -329,77 +306,13 @@ static struct task_desc *register_pid(unsigned long pid, const char *comm)
         BUG_ON(!tasks);
         tasks[task->nr] = task;
 
-        printk("registered task #%ld, PID %ld (%s)\n", nr_tasks, pid, comm);
+        if (verbose)
+                printf("registered task #%ld, PID %ld (%s)\n", nr_tasks, pid, comm);
 
         return task;
 }
 
 
-static int first_trace_line = 1;
-
-static nsec_t first_timestamp;
-static nsec_t prev_timestamp;
-
-void parse_line(char *line);
-
-void parse_line(char *line)
-{
-        unsigned long param1 = 0, param2 = 0;
-        char comm[COMM_LEN], comm2[COMM_LEN];
-        unsigned long pid, pid2, timestamp0;
-        struct task_desc *task, *task2;
-        char func_str[SYM_LEN];
-        nsec_t timestamp;
-        int ret;
-
-        //"   <idle> 0     0D.s3    0us+: try_to_wake_up <events/0 9> (1 0)"
-        ret = sscanf(line, "%20s %5ld %*s %ldus%*c:"
-                           " %128s <%20s %ld> (%ld %ld)\n",
-                comm, &pid, &timestamp0,
-                func_str, comm2, &pid2, &param1, &param2);
-        dprintk("ret: %d\n", ret);
-        if (ret != 8)
-                return;
-
-        timestamp = timestamp0 * 1000LL;
-
-        if (first_trace_line) {
-                first_trace_line = 0;
-                first_timestamp = timestamp;
-        }
-
-        timestamp -= first_timestamp;
-        BUG_ON(timestamp < prev_timestamp);
-        prev_timestamp = timestamp;
-
-        dprintk("parsed: %s - %ld %Ld: %s - <%s %ld> (%ld %ld)\n",
-                comm,
-                pid,
-                timestamp,
-                func_str,
-                comm2,
-                pid2,
-                param1,
-                param2);
-
-        task = register_pid(pid, comm);
-        task2 = register_pid(pid2, comm2);
-
-        if (!strcmp(func_str, "update_curr")) {
-                dprintk("%Ld: task %ld runs for %ld nsecs\n",
-                        timestamp, task->nr, param1);
-                add_sched_event_run(task, timestamp, param1);
-        } else if (!strcmp(func_str, "try_to_wake_up")) {
-                dprintk("%Ld: task %ld wakes up task %ld\n",
-                        timestamp, task->nr, task2->nr);
-                add_sched_event_wakeup(task, timestamp, task2);
-        } else if (!strcmp(func_str, "deactivate_task")) {
-                dprintk("%Ld: task %ld goes to sleep (uninterruptible: %ld)\n",
-                        timestamp, task->nr, param1);
-                add_sched_event_sleep(task, timestamp, param1);
-        }
-}
-
 static void print_task_traces(void)
 {
         struct task_desc *task;
@@ -407,7 +320,7 @@ static void print_task_traces(void)
 
         for (i = 0; i < nr_tasks; i++) {
                 task = tasks[i];
-                printk("task %6ld (%20s:%10ld), nr_events: %ld\n",
+                printf("task %6ld (%20s:%10ld), nr_events: %ld\n",
                         task->nr, task->comm, task->pid, task->nr_events);
         }
 }
@@ -437,40 +350,16 @@ process_sched_event(struct task_desc *this_task __used, struct sched_event *even
         now = get_nsecs();
         delta = start_time + event->timestamp - now;
 
-        dprintk("task %ld, event #%ld, %Ld, delta: %.3f (%Ld)\n",
-                this_task->nr, event->nr, event->timestamp,
-                (double)delta/1e6, delta);
-
-        if (0 && delta > 0) {
-                dprintk("%.3f: task %ld FIX %.3f\n",
-                        (double)event->timestamp/1e6,
-                        this_task->nr,
-                        (double)delta/1e6);
-                sleep_nsecs(start_time + event->timestamp - now);
-                nr_sleep_corrections++;
-        }
-
         switch (event->type) {
                 case SCHED_EVENT_RUN:
-                        dprintk("%.3f: task %ld RUN for %.3f\n",
-                                (double)event->timestamp/1e6,
-                                this_task->nr,
-                                (double)event->duration/1e6);
                         burn_nsecs(event->duration);
                         break;
                 case SCHED_EVENT_SLEEP:
-                        dprintk("%.3f: task %ld %s SLEEP\n",
-                                (double)event->timestamp/1e6,
-                                this_task->nr, event->wait_sem ? "" : "SKIP");
                         if (event->wait_sem)
                                 ret = sem_wait(event->wait_sem);
                         BUG_ON(ret);
                         break;
                 case SCHED_EVENT_WAKEUP:
-                        dprintk("%.3f: task %ld WAKEUP => task %ld\n",
-                                (double)event->timestamp/1e6,
-                                this_task->nr,
-                                event->wakee->nr);
                         if (event->wait_sem)
                                 ret = sem_post(event->wait_sem);
                         BUG_ON(ret);
@@ -511,14 +400,10 @@ static nsec_t get_cpu_usage_nsec_self(void)
         BUG_ON(!file);
 
         while ((chars = getline(&line, &len, file)) != -1) {
-                dprintk("got line with length %zu :\n", chars);
-                dprintk("%s", line);
                 ret = sscanf(line, "se.sum_exec_runtime : %ld.%06ld\n",
                         &msecs, &nsecs);
                 if (ret == 2) {
                         total = msecs*1e6 + nsecs;
-                        dprintk("total: (%ld.%06ld) %Ld\n",
-                                msecs, nsecs, total);
                         break;
                 }
         }
@@ -536,19 +421,16 @@ static void *thread_func(void *ctx)
         unsigned long i, ret;
         char comm2[22];
 
-        dprintk("task %ld started up.\n", this_task->nr);
         sprintf(comm2, ":%s", this_task->comm);
         prctl(PR_SET_NAME, comm2);
 
 again:
         ret = sem_post(&this_task->ready_for_work);
         BUG_ON(ret);
-        D();
         ret = pthread_mutex_lock(&start_work_mutex);
         BUG_ON(ret);
         ret = pthread_mutex_unlock(&start_work_mutex);
         BUG_ON(ret);
-        D();
 
         cpu_usage_0 = get_cpu_usage_nsec_self();
 
@@ -560,19 +442,13 @@ again:
         cpu_usage_1 = get_cpu_usage_nsec_self();
         this_task->cpu_usage = cpu_usage_1 - cpu_usage_0;
 
-        dprintk("task %ld cpu usage: %0.3f msecs\n",
-                this_task->nr, (double)this_task->cpu_usage / 1e6);
-
-        D();
         ret = sem_post(&this_task->work_done_sem);
         BUG_ON(ret);
-        D();
 
         ret = pthread_mutex_lock(&work_done_wait_mutex);
         BUG_ON(ret);
         ret = pthread_mutex_unlock(&work_done_wait_mutex);
         BUG_ON(ret);
-        D();
 
         goto again;
 }
@@ -614,9 +490,7 @@ static void wait_for_tasks(void)
         struct task_desc *task;
         unsigned long i, ret;
 
-        DP();
         start_time = get_nsecs();
-        DP();
         cpu_usage = 0;
         pthread_mutex_unlock(&work_done_wait_mutex);
 
@@ -633,24 +507,6 @@ static void wait_for_tasks(void)
 
         pthread_mutex_unlock(&start_work_mutex);
 
-#if 0
-        for (i = 0; i < nr_tasks; i++) {
-                unsigned long missed;
-
-                task = tasks[i];
-                while (task->curr_event + 1 < task->nr_events) {
-                        dprintk("parent waiting for %ld (%ld != %ld)\n",
-                                i, task->curr_event, task->nr_events);
-                        sleep_nsecs(100000000);
-                }
-                missed = task->nr_events - 1 - task->curr_event;
-                if (missed)
-                        printk("task %ld missed events: %ld\n", i, missed);
-                ret = sem_post(&task->sleep_sem);
-                BUG_ON(ret);
-        }
-#endif
-        DP();
         for (i = 0; i < nr_tasks; i++) {
                 task = tasks[i];
                 ret = sem_wait(&task->work_done_sem);
@@ -687,16 +543,16 @@ static void parse_trace(void)
 {
         __cmd_sched();
 
-        printk("nr_run_events:        %ld\n", nr_run_events);
-        printk("nr_sleep_events:      %ld\n", nr_sleep_events);
-        printk("nr_wakeup_events:     %ld\n", nr_wakeup_events);
+        printf("nr_run_events:        %ld\n", nr_run_events);
+        printf("nr_sleep_events:      %ld\n", nr_sleep_events);
+        printf("nr_wakeup_events:     %ld\n", nr_wakeup_events);
 
         if (targetless_wakeups)
-                printk("target-less wakeups:  %ld\n", targetless_wakeups);
+                printf("target-less wakeups:  %ld\n", targetless_wakeups);
         if (multitarget_wakeups)
-                printk("multi-target wakeups: %ld\n", multitarget_wakeups);
+                printf("multi-target wakeups: %ld\n", multitarget_wakeups);
         if (nr_run_events_optimized)
-                printk("run events optimized: %ld\n",
+                printf("run events optimized: %ld\n",
                         nr_run_events_optimized);
 }
 
@@ -728,17 +584,17 @@ static void run_one_test(void)
                 run_avg = delta;
         run_avg = (run_avg*9 + delta)/10;
 
-        printk("#%-3ld: %0.3f, ",
+        printf("#%-3ld: %0.3f, ",
                 nr_runs, (double)delta/1000000.0);
 
 #if 0
-        printk("%0.2f +- %0.2f, ",
+        printf("%0.2f +- %0.2f, ",
                 (double)avg_delta/1e6, (double)std_dev/1e6);
 #endif
-        printk("ravg: %0.2f, ",
+        printf("ravg: %0.2f, ",
                 (double)run_avg/1e6);
 
-        printk("cpu: %0.2f / %0.2f",
+        printf("cpu: %0.2f / %0.2f",
                 (double)cpu_usage/1e6, (double)runavg_cpu_usage/1e6);
 
 #if 0
@@ -746,15 +602,15 @@ static void run_one_test(void)
          * rusage statistics done by the parent, these are less
          * accurate than the sum_exec_runtime based statistics:
          */
-        printk(" [%0.2f / %0.2f]",
+        printf(" [%0.2f / %0.2f]",
                 (double)parent_cpu_usage/1e6,
                 (double)runavg_parent_cpu_usage/1e6);
 #endif
 
-        printk("\n");
+        printf("\n");
 
         if (nr_sleep_corrections)
-                printk(" (%ld sleep corrections)\n", nr_sleep_corrections);
+                printf(" (%ld sleep corrections)\n", nr_sleep_corrections);
         nr_sleep_corrections = 0;
 }
 
@@ -766,13 +622,13 @@ static void test_calibrations(void)
         burn_nsecs(1e6);
         T1 = get_nsecs();
 
-        printk("the run test took %Ld nsecs\n", T1-T0);
+        printf("the run test took %Ld nsecs\n", T1-T0);
 
         T0 = get_nsecs();
         sleep_nsecs(1e6);
         T1 = get_nsecs();
 
-        printk("the sleep test took %Ld nsecs\n", T1-T0);
+        printf("the sleep test took %Ld nsecs\n", T1-T0);
 }
 
 static int
@@ -820,12 +676,14 @@ process_sched_wakeup_event(struct trace_wakeup_event *wakeup_event, struct event
 {
         struct task_desc *waker, *wakee;
 
-        printf("sched_wakeup event %p\n", event);
+        if (verbose) {
+                printf("sched_wakeup event %p\n", event);
 
-        printf(" ... pid %d woke up %s/%d\n",
-                wakeup_event->common_pid,
-                wakeup_event->comm,
-                wakeup_event->pid);
+                printf(" ... pid %d woke up %s/%d\n",
+                        wakeup_event->common_pid,
+                        wakeup_event->comm,
+                        wakeup_event->pid);
+        }
 
         waker = register_pid(wakeup_event->common_pid, "<unknown>");
         wakee = register_pid(wakeup_event->pid, wakeup_event->comm);
@@ -863,7 +721,9 @@ process_sched_switch_event(struct trace_switch_event *switch_event, struct event
         u64 timestamp0;
         s64 delta;
 
-        printf("sched_switch event %p\n", event);
+        if (verbose)
+                printf("sched_switch event %p\n", event);
+
         if (cpu >= MAX_CPUS || cpu < 0)
                 return;
 
@@ -876,10 +736,12 @@ process_sched_switch_event(struct trace_switch_event *switch_event, struct event
         if (delta < 0)
                 die("hm, delta: %Ld < 0 ?\n", delta);
 
-        printf(" ... switch from %s/%d to %s/%d [ran %Ld nsecs]\n",
-                switch_event->prev_comm, switch_event->prev_pid,
-                switch_event->next_comm, switch_event->next_pid,
-                delta);
+        if (verbose) {
+                printf(" ... switch from %s/%d to %s/%d [ran %Ld nsecs]\n",
+                        switch_event->prev_comm, switch_event->prev_pid,
+                        switch_event->next_comm, switch_event->next_pid,
+                        delta);
+        }
 
         prev = register_pid(switch_event->prev_pid, switch_event->prev_comm);
         next = register_pid(switch_event->next_pid, switch_event->next_comm);
@@ -887,6 +749,7 @@ process_sched_switch_event(struct trace_switch_event *switch_event, struct event
         cpu_last_switched[cpu] = timestamp;
 
         add_sched_event_run(prev, timestamp, delta);
+        add_sched_event_sleep(prev, timestamp, switch_event->prev_state);
 }
 
 struct trace_fork_event {
@@ -908,9 +771,11 @@ static void
 process_sched_fork_event(struct trace_fork_event *fork_event, struct event *event,
                   int cpu __used, u64 timestamp __used, struct thread *thread __used)
 {
-        printf("sched_fork event %p\n", event);
-        printf("... parent: %s/%d\n", fork_event->parent_comm, fork_event->parent_pid);
-        printf("...  child: %s/%d\n", fork_event->child_comm, fork_event->child_pid);
+        if (verbose) {
+                printf("sched_fork event %p\n", event);
+                printf("... parent: %s/%d\n", fork_event->parent_comm, fork_event->parent_pid);
+                printf("...  child: %s/%d\n", fork_event->child_comm, fork_event->child_pid);
+        }
         register_pid(fork_event->parent_pid, fork_event->parent_comm);
         register_pid(fork_event->child_pid, fork_event->child_comm);
 }
@@ -918,11 +783,12 @@ process_sched_fork_event(struct trace_fork_event *fork_event, struct event *even
 static void process_sched_exit_event(struct event *event,
                   int cpu __used, u64 timestamp __used, struct thread *thread __used)
 {
-        printf("sched_exit event %p\n", event);
+        if (verbose)
+                printf("sched_exit event %p\n", event);
 }
 
 static void
-process_raw_event(event_t *raw_event, void *more_data,
+process_raw_event(event_t *raw_event __used, void *more_data,
                   int cpu, u64 timestamp, struct thread *thread)
 {
         struct {
@@ -935,14 +801,6 @@ process_raw_event(event_t *raw_event, void *more_data,
         type = trace_parse_common_type(raw->data);
         event = trace_find_event(type);
 
-        /*
-         * FIXME: better resolve from pid from the struct trace_entry
-         * field, although it should be the same than this perf
-         * event pid
-         */
-        printf("id %d, type: %d, event: %s\n",
-                raw_event->header.type, type, event->name);
-
         if (!strcmp(event->name, "sched_switch"))
                 process_sched_switch_event(more_data, event, cpu, timestamp, thread);
         if (!strcmp(event->name, "sched_wakeup"))
@@ -1197,7 +1055,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __used)
         add_cross_task_wakeups();
 
         create_tasks();
-        printk("------------------------------------------------------------\n");
+        printf("------------------------------------------------------------\n");
         for (i = 0; i < nr_iterations; i++)
                 run_one_test();