aboutsummaryrefslogtreecommitdiffstats
path: root/tools/perf
diff options
context:
space:
mode:
authorIngo Molnar <mingo@elte.hu>2009-09-11 06:12:54 -0400
committerIngo Molnar <mingo@elte.hu>2009-09-13 04:22:38 -0400
commitfbf9482911825f965829567aea8acff3bbc5279c (patch)
treef7e4e18ab46550906d7981ef7423acd84f2f9da7 /tools/perf
parentec156764d424dd67283c2cd5e9f6f1b8388364ac (diff)
perf sched: Implement the scheduling workload replay engine
Integrate the schedbench.c bits with the raw trace events that we get from the perf machinery, and activate the workload replayer/simulator. Example of a captured 'make -j' workload: $ perf sched run measurement overhead: 90 nsecs sleep measurement overhead: 2724743 nsecs the run test took 1000081 nsecs the sleep test took 2981111 nsecs version = 0.5 ... nr_run_events: 70 nr_sleep_events: 66 nr_wakeup_events: 9 target-less wakeups: 71 multi-target wakeups: 47 run events optimized: 139 task 0 ( perf: 6607), nr_events: 2 task 1 ( perf: 6608), nr_events: 6 task 2 ( : 0), nr_events: 1 task 3 ( make: 6609), nr_events: 5 task 4 ( sh: 6610), nr_events: 4 task 5 ( make: 6611), nr_events: 6 task 6 ( sh: 6612), nr_events: 4 task 7 ( make: 6613), nr_events: 5 task 8 ( migration/11: 25), nr_events: 1 task 9 ( migration/13: 29), nr_events: 1 task 10 ( migration/15: 33), nr_events: 1 task 11 ( migration/9: 21), nr_events: 1 task 12 ( sh: 6614), nr_events: 4 task 13 ( make: 6615), nr_events: 5 task 14 ( sh: 6616), nr_events: 4 task 15 ( make: 6617), nr_events: 7 task 16 ( migration/3: 9), nr_events: 1 task 17 ( migration/5: 13), nr_events: 1 task 18 ( migration/7: 17), nr_events: 1 task 19 ( migration/1: 5), nr_events: 1 task 20 ( sh: 6618), nr_events: 4 task 21 ( make: 6619), nr_events: 5 task 22 ( sh: 6620), nr_events: 4 task 23 ( make: 6621), nr_events: 10 task 24 ( sh: 6623), nr_events: 3 task 25 ( gcc: 6624), nr_events: 4 task 26 ( gcc: 6625), nr_events: 4 task 27 ( gcc: 6626), nr_events: 5 task 28 ( collect2: 6627), nr_events: 5 task 29 ( sh: 6622), nr_events: 1 task 30 ( make: 6628), nr_events: 7 task 31 ( sh: 6630), nr_events: 4 task 32 ( gcc: 6631), nr_events: 4 task 33 ( sh: 6629), nr_events: 1 task 34 ( gcc: 6632), nr_events: 4 task 35 ( gcc: 6633), nr_events: 4 task 36 ( collect2: 6634), nr_events: 4 task 37 ( make: 6635), nr_events: 8 task 38 ( sh: 6637), nr_events: 4 task 39 ( sh: 6636), nr_events: 1 task 40 ( gcc: 6638), nr_events: 4 task 41 ( gcc: 6639), nr_events: 4 task 42 ( gcc: 6640), nr_events: 4 task 43 ( collect2: 6641), nr_events: 4 task 44 ( make: 6642), nr_events: 6 task 45 ( sh: 6643), nr_events: 5 task 46 ( sh: 6644), nr_events: 3 task 47 ( sh: 6645), nr_events: 4 task 48 ( make: 6646), nr_events: 6 task 49 ( sh: 6647), nr_events: 3 task 50 ( make: 6648), nr_events: 5 task 51 ( sh: 6649), nr_events: 5 task 52 ( sh: 6650), nr_events: 6 task 53 ( make: 6651), nr_events: 4 task 54 ( make: 6652), nr_events: 5 task 55 ( make: 6653), nr_events: 4 task 56 ( make: 6654), nr_events: 4 task 57 ( make: 6655), nr_events: 5 task 58 ( sh: 6656), nr_events: 4 task 59 ( gcc: 6657), nr_events: 9 task 60 ( ksoftirqd/3: 10), nr_events: 1 task 61 ( gcc: 6658), nr_events: 4 task 62 ( make: 6659), nr_events: 5 task 63 ( sh: 6660), nr_events: 3 task 64 ( gcc: 6661), nr_events: 5 task 65 ( collect2: 6662), nr_events: 4 ------------------------------------------------------------ #1 : 256.745, ravg: 256.74, cpu: 0.00 / 0.00 #2 : 439.372, ravg: 275.01, cpu: 0.00 / 0.00 #3 : 411.971, ravg: 288.70, cpu: 0.00 / 0.00 #4 : 385.500, ravg: 298.38, cpu: 0.00 / 0.00 #5 : 366.526, ravg: 305.20, cpu: 0.00 / 0.00 #6 : 381.281, ravg: 312.81, cpu: 0.00 / 0.00 #7 : 410.756, ravg: 322.60, cpu: 0.00 / 0.00 #8 : 368.009, ravg: 327.14, cpu: 0.00 / 0.00 #9 : 408.098, ravg: 335.24, cpu: 0.00 / 0.00 #10 : 368.582, ravg: 338.57, cpu: 0.00 / 0.00 I.e. we successfully analyzed the trace, replayed it via real threads and measured the replayed workload's scheduling properties. This is how it looked like in 'top' output: PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 7164 mingo 20 0 1434m 8080 888 R 57.0 0.1 0:02.04 :perf 7165 mingo 20 0 1434m 8080 888 R 41.8 0.1 0:01.52 :perf 7228 mingo 20 0 1434m 8080 888 R 39.8 0.1 0:01.44 :gcc 7225 mingo 20 0 1434m 8080 888 R 33.8 0.1 0:01.26 :gcc 7202 mingo 20 0 1434m 8080 888 R 31.2 0.1 0:01.16 :sh 7222 mingo 20 0 1434m 8080 888 R 25.2 0.1 0:00.96 :sh 7211 mingo 20 0 1434m 8080 888 R 21.9 0.1 0:00.82 :sh 7213 mingo 20 0 1434m 8080 888 D 19.2 0.1 0:00.74 :sh 7194 mingo 20 0 1434m 8080 888 D 18.6 0.1 0:00.72 :make There's still various kinks in it - more patches to come. Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Mike Galbraith <efault@gmx.de> Cc: Paul Mackerras <paulus@samba.org> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> LKML-Reference: <new-submission> Signed-off-by: Ingo Molnar <mingo@elte.hu>
Diffstat (limited to 'tools/perf')
-rw-r--r--tools/perf/builtin-sched.c152
1 files changed, 134 insertions, 18 deletions
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index c66e6a321371..6ec4f51d536b 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -57,7 +57,7 @@ static u64 sample_type;
57 57
58#define BUG_ON(x) assert(!(x)) 58#define BUG_ON(x) assert(!(x))
59 59
60#define DEBUG 1 60#define DEBUG 0
61 61
62typedef unsigned long long nsec_t; 62typedef unsigned long long nsec_t;
63 63
@@ -238,15 +238,14 @@ static struct sched_event *last_event(struct task_desc *task)
238} 238}
239 239
240static void 240static void
241add_sched_event_run(struct task_desc *task, nsec_t timestamp, 241add_sched_event_run(struct task_desc *task, nsec_t timestamp, u64 duration)
242 unsigned long duration)
243{ 242{
244 struct sched_event *event, *curr_event = last_event(task); 243 struct sched_event *event, *curr_event = last_event(task);
245 244
246 /* 245 /*
247 * optimize an existing RUN event by merging this one 246 * optimize an existing RUN event by merging this one
248 * to it: 247 * to it:
249 */ 248 */
250 if (curr_event && curr_event->type == SCHED_EVENT_RUN) { 249 if (curr_event && curr_event->type == SCHED_EVENT_RUN) {
251 nr_run_events_optimized++; 250 nr_run_events_optimized++;
252 curr_event->duration += duration; 251 curr_event->duration += duration;
@@ -376,7 +375,7 @@ void parse_line(char *line)
376 dprintk("parsed: %s - %ld %Ld: %s - <%s %ld> (%ld %ld)\n", 375 dprintk("parsed: %s - %ld %Ld: %s - <%s %ld> (%ld %ld)\n",
377 comm, 376 comm,
378 pid, 377 pid,
379 timestamp, 378 timestamp,
380 func_str, 379 func_str,
381 comm2, 380 comm2,
382 pid2, 381 pid2,
@@ -429,7 +428,7 @@ static void add_cross_task_wakeups(void)
429} 428}
430 429
431static void 430static void
432process_sched_event(struct task_desc *this_task, struct sched_event *event) 431process_sched_event(struct task_desc *this_task __used, struct sched_event *event)
433{ 432{
434 int ret = 0; 433 int ret = 0;
435 nsec_t now; 434 nsec_t now;
@@ -744,9 +743,9 @@ static void run_one_test(void)
744 743
745#if 0 744#if 0
746 /* 745 /*
747 * rusage statistics done by the parent, these are less 746 * rusage statistics done by the parent, these are less
748 * accurate than the sum_exec_runtime based statistics: 747 * accurate than the sum_exec_runtime based statistics:
749 */ 748 */
750 printk(" [%0.2f / %0.2f]", 749 printk(" [%0.2f / %0.2f]",
751 (double)parent_cpu_usage/1e6, 750 (double)parent_cpu_usage/1e6,
752 (double)runavg_parent_cpu_usage/1e6); 751 (double)runavg_parent_cpu_usage/1e6);
@@ -798,16 +797,128 @@ process_comm_event(event_t *event, unsigned long offset, unsigned long head)
798 return 0; 797 return 0;
799} 798}
800 799
801static void process_sched_wakeup_event(struct event *event, 800struct trace_wakeup_event {
801 u32 size;
802
803 u16 common_type;
804 u8 common_flags;
805 u8 common_preempt_count;
806 u32 common_pid;
807 u32 common_tgid;
808
809 char comm[16];
810 u32 pid;
811
812 u32 prio;
813 u32 success;
814 u32 cpu;
815};
816
817static void
818process_sched_wakeup_event(struct trace_wakeup_event *wakeup_event, struct event *event,
802 int cpu __used, u64 timestamp __used, struct thread *thread __used) 819 int cpu __used, u64 timestamp __used, struct thread *thread __used)
803{ 820{
821 struct task_desc *waker, *wakee;
822
804 printf("sched_wakeup event %p\n", event); 823 printf("sched_wakeup event %p\n", event);
824
825 printf(" ... pid %d woke up %s/%d\n",
826 wakeup_event->common_pid,
827 wakeup_event->comm,
828 wakeup_event->pid);
829
830 waker = register_pid(wakeup_event->common_pid, "<unknown>");
831 wakee = register_pid(wakeup_event->pid, wakeup_event->comm);
832
833 add_sched_event_wakeup(waker, timestamp, wakee);
805} 834}
806 835
807static void process_sched_switch_event(struct event *event, 836struct trace_switch_event {
837 u32 size;
838
839 u16 common_type;
840 u8 common_flags;
841 u8 common_preempt_count;
842 u32 common_pid;
843 u32 common_tgid;
844
845 char prev_comm[16];
846 u32 prev_pid;
847 u32 prev_prio;
848 u64 prev_state;
849 char next_comm[16];
850 u32 next_pid;
851 u32 next_prio;
852};
853
854#define MAX_CPUS 4096
855
856unsigned long cpu_last_switched[MAX_CPUS];
857
858static void
859process_sched_switch_event(struct trace_switch_event *switch_event, struct event *event,
808 int cpu __used, u64 timestamp __used, struct thread *thread __used) 860 int cpu __used, u64 timestamp __used, struct thread *thread __used)
809{ 861{
862 struct task_desc *prev, *next;
863 u64 timestamp0;
864 s64 delta;
865
810 printf("sched_switch event %p\n", event); 866 printf("sched_switch event %p\n", event);
867 if (cpu >= MAX_CPUS || cpu < 0)
868 return;
869
870 timestamp0 = cpu_last_switched[cpu];
871 if (timestamp0)
872 delta = timestamp - timestamp0;
873 else
874 delta = 0;
875
876 if (delta < 0)
877 die("hm, delta: %Ld < 0 ?\n", delta);
878
879 printf(" ... switch from %s/%d to %s/%d [ran %Ld nsecs]\n",
880 switch_event->prev_comm, switch_event->prev_pid,
881 switch_event->next_comm, switch_event->next_pid,
882 delta);
883
884 prev = register_pid(switch_event->prev_pid, switch_event->prev_comm);
885 next = register_pid(switch_event->next_pid, switch_event->next_comm);
886
887 cpu_last_switched[cpu] = timestamp;
888
889 add_sched_event_run(prev, timestamp, delta);
890}
891
892struct trace_fork_event {
893 u32 size;
894
895 u16 common_type;
896 u8 common_flags;
897 u8 common_preempt_count;
898 u32 common_pid;
899 u32 common_tgid;
900
901 char parent_comm[16];
902 u32 parent_pid;
903 char child_comm[16];
904 u32 child_pid;
905};
906
907static void
908process_sched_fork_event(struct trace_fork_event *fork_event, struct event *event,
909 int cpu __used, u64 timestamp __used, struct thread *thread __used)
910{
911 printf("sched_fork event %p\n", event);
912 printf("... parent: %s/%d\n", fork_event->parent_comm, fork_event->parent_pid);
913 printf("... child: %s/%d\n", fork_event->child_comm, fork_event->child_pid);
914 register_pid(fork_event->parent_pid, fork_event->parent_comm);
915 register_pid(fork_event->child_pid, fork_event->child_comm);
916}
917
918static void process_sched_exit_event(struct event *event,
919 int cpu __used, u64 timestamp __used, struct thread *thread __used)
920{
921 printf("sched_exit event %p\n", event);
811} 922}
812 923
813static void 924static void
@@ -833,9 +944,15 @@ process_raw_event(event_t *raw_event, void *more_data,
833 raw_event->header.type, type, event->name); 944 raw_event->header.type, type, event->name);
834 945
835 if (!strcmp(event->name, "sched_switch")) 946 if (!strcmp(event->name, "sched_switch"))
836 process_sched_switch_event(event, cpu, timestamp, thread); 947 process_sched_switch_event(more_data, event, cpu, timestamp, thread);
837 if (!strcmp(event->name, "sched_wakeup")) 948 if (!strcmp(event->name, "sched_wakeup"))
838 process_sched_wakeup_event(event, cpu, timestamp, thread); 949 process_sched_wakeup_event(more_data, event, cpu, timestamp, thread);
950 if (!strcmp(event->name, "sched_wakeup_new"))
951 process_sched_wakeup_event(more_data, event, cpu, timestamp, thread);
952 if (!strcmp(event->name, "sched_process_fork"))
953 process_sched_fork_event(more_data, event, cpu, timestamp, thread);
954 if (!strcmp(event->name, "sched_process_exit"))
955 process_sched_exit_event(event, cpu, timestamp, thread);
839} 956}
840 957
841static int 958static int
@@ -1053,7 +1170,7 @@ static const struct option options[] = {
1053 1170
1054int cmd_sched(int argc, const char **argv, const char *prefix __used) 1171int cmd_sched(int argc, const char **argv, const char *prefix __used)
1055{ 1172{
1056 long nr_iterations = LONG_MAX, i; 1173 long nr_iterations = 10, i;
1057 1174
1058 symbol__init(); 1175 symbol__init();
1059 page_size = getpagesize(); 1176 page_size = getpagesize();
@@ -1068,8 +1185,7 @@ int cmd_sched(int argc, const char **argv, const char *prefix __used)
1068 usage_with_options(annotate_usage, options); 1185 usage_with_options(annotate_usage, options);
1069 } 1186 }
1070 1187
1071 1188// setup_pager();
1072 setup_pager();
1073 1189
1074 calibrate_run_measurement_overhead(); 1190 calibrate_run_measurement_overhead();
1075 calibrate_sleep_measurement_overhead(); 1191 calibrate_sleep_measurement_overhead();