diff options
author | Ingo Molnar <mingo@elte.hu> | 2009-09-11 06:12:54 -0400 |
---|---|---|
committer | Ingo Molnar <mingo@elte.hu> | 2009-09-13 04:22:38 -0400 |
commit | fbf9482911825f965829567aea8acff3bbc5279c (patch) | |
tree | f7e4e18ab46550906d7981ef7423acd84f2f9da7 /tools/perf | |
parent | ec156764d424dd67283c2cd5e9f6f1b8388364ac (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.c | 152 |
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 | ||
62 | typedef unsigned long long nsec_t; | 62 | typedef 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 | ||
240 | static void | 240 | static void |
241 | add_sched_event_run(struct task_desc *task, nsec_t timestamp, | 241 | add_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 | ||
431 | static void | 430 | static void |
432 | process_sched_event(struct task_desc *this_task, struct sched_event *event) | 431 | process_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 | ||
801 | static void process_sched_wakeup_event(struct event *event, | 800 | struct 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 | |||
817 | static void | ||
818 | process_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 | ||
807 | static void process_sched_switch_event(struct event *event, | 836 | struct 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 | |||
856 | unsigned long cpu_last_switched[MAX_CPUS]; | ||
857 | |||
858 | static void | ||
859 | process_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 | |||
892 | struct 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 | |||
907 | static void | ||
908 | process_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 | |||
918 | static 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 | ||
813 | static void | 924 | static 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 | ||
841 | static int | 958 | static int |
@@ -1053,7 +1170,7 @@ static const struct option options[] = { | |||
1053 | 1170 | ||
1054 | int cmd_sched(int argc, const char **argv, const char *prefix __used) | 1171 | int 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(); |