5 #include "util/cache.h"
6 #include "util/symbol.h"
7 #include "util/thread.h"
8 #include "util/header.h"
9 #include "util/session.h"
11 #include "util/parse-options.h"
12 #include "util/trace-event.h"
14 #include "util/debug.h"
15 #include "util/data_map.h"
17 #include <sys/prctl.h>
19 #include <semaphore.h>
23 static char const *input_name
= "perf.data";
25 static u64 sample_type
;
27 static char default_sort_order
[] = "avg, max, switch, runtime";
28 static char *sort_order
= default_sort_order
;
30 static int profile_cpu
= -1;
32 #define PR_SET_NAME 15 /* Set process name */
35 static u64 run_measurement_overhead
;
36 static u64 sleep_measurement_overhead
;
43 static unsigned long nr_tasks
;
52 unsigned long nr_events
;
53 unsigned long curr_event
;
54 struct sched_atom
**atoms
;
65 enum sched_event_type
{
69 SCHED_EVENT_MIGRATION
,
73 enum sched_event_type type
;
79 struct task_desc
*wakee
;
82 static struct task_desc
*pid_to_task
[MAX_PID
];
84 static struct task_desc
**tasks
;
86 static pthread_mutex_t start_work_mutex
= PTHREAD_MUTEX_INITIALIZER
;
87 static u64 start_time
;
89 static pthread_mutex_t work_done_wait_mutex
= PTHREAD_MUTEX_INITIALIZER
;
91 static unsigned long nr_run_events
;
92 static unsigned long nr_sleep_events
;
93 static unsigned long nr_wakeup_events
;
95 static unsigned long nr_sleep_corrections
;
96 static unsigned long nr_run_events_optimized
;
98 static unsigned long targetless_wakeups
;
99 static unsigned long multitarget_wakeups
;
101 static u64 cpu_usage
;
102 static u64 runavg_cpu_usage
;
103 static u64 parent_cpu_usage
;
104 static u64 runavg_parent_cpu_usage
;
106 static unsigned long nr_runs
;
107 static u64 sum_runtime
;
108 static u64 sum_fluct
;
111 static unsigned long replay_repeat
= 10;
112 static unsigned long nr_timestamps
;
113 static unsigned long nr_unordered_timestamps
;
114 static unsigned long nr_state_machine_bugs
;
115 static unsigned long nr_context_switch_bugs
;
116 static unsigned long nr_events
;
117 static unsigned long nr_lost_chunks
;
118 static unsigned long nr_lost_events
;
120 #define TASK_STATE_TO_CHAR_STR "RSDTtZX"
130 struct list_head list
;
131 enum thread_state state
;
139 struct list_head work_list
;
140 struct thread
*thread
;
149 typedef int (*sort_fn_t
)(struct work_atoms
*, struct work_atoms
*);
151 static struct rb_root atom_root
, sorted_atom_root
;
153 static u64 all_runtime
;
154 static u64 all_count
;
157 static u64
get_nsecs(void)
161 clock_gettime(CLOCK_MONOTONIC
, &ts
);
163 return ts
.tv_sec
* 1000000000ULL + ts
.tv_nsec
;
166 static void burn_nsecs(u64 nsecs
)
168 u64 T0
= get_nsecs(), T1
;
172 } while (T1
+ run_measurement_overhead
< T0
+ nsecs
);
175 static void sleep_nsecs(u64 nsecs
)
179 ts
.tv_nsec
= nsecs
% 999999999;
180 ts
.tv_sec
= nsecs
/ 999999999;
182 nanosleep(&ts
, NULL
);
185 static void calibrate_run_measurement_overhead(void)
187 u64 T0
, T1
, delta
, min_delta
= 1000000000ULL;
190 for (i
= 0; i
< 10; i
++) {
195 min_delta
= min(min_delta
, delta
);
197 run_measurement_overhead
= min_delta
;
199 printf("run measurement overhead: %Ld nsecs\n", min_delta
);
202 static void calibrate_sleep_measurement_overhead(void)
204 u64 T0
, T1
, delta
, min_delta
= 1000000000ULL;
207 for (i
= 0; i
< 10; i
++) {
212 min_delta
= min(min_delta
, delta
);
215 sleep_measurement_overhead
= min_delta
;
217 printf("sleep measurement overhead: %Ld nsecs\n", min_delta
);
220 static struct sched_atom
*
221 get_new_event(struct task_desc
*task
, u64 timestamp
)
223 struct sched_atom
*event
= zalloc(sizeof(*event
));
224 unsigned long idx
= task
->nr_events
;
227 event
->timestamp
= timestamp
;
231 size
= sizeof(struct sched_atom
*) * task
->nr_events
;
232 task
->atoms
= realloc(task
->atoms
, size
);
233 BUG_ON(!task
->atoms
);
235 task
->atoms
[idx
] = event
;
240 static struct sched_atom
*last_event(struct task_desc
*task
)
242 if (!task
->nr_events
)
245 return task
->atoms
[task
->nr_events
- 1];
249 add_sched_event_run(struct task_desc
*task
, u64 timestamp
, u64 duration
)
251 struct sched_atom
*event
, *curr_event
= last_event(task
);
254 * optimize an existing RUN event by merging this one
257 if (curr_event
&& curr_event
->type
== SCHED_EVENT_RUN
) {
258 nr_run_events_optimized
++;
259 curr_event
->duration
+= duration
;
263 event
= get_new_event(task
, timestamp
);
265 event
->type
= SCHED_EVENT_RUN
;
266 event
->duration
= duration
;
272 add_sched_event_wakeup(struct task_desc
*task
, u64 timestamp
,
273 struct task_desc
*wakee
)
275 struct sched_atom
*event
, *wakee_event
;
277 event
= get_new_event(task
, timestamp
);
278 event
->type
= SCHED_EVENT_WAKEUP
;
279 event
->wakee
= wakee
;
281 wakee_event
= last_event(wakee
);
282 if (!wakee_event
|| wakee_event
->type
!= SCHED_EVENT_SLEEP
) {
283 targetless_wakeups
++;
286 if (wakee_event
->wait_sem
) {
287 multitarget_wakeups
++;
291 wakee_event
->wait_sem
= zalloc(sizeof(*wakee_event
->wait_sem
));
292 sem_init(wakee_event
->wait_sem
, 0, 0);
293 wakee_event
->specific_wait
= 1;
294 event
->wait_sem
= wakee_event
->wait_sem
;
300 add_sched_event_sleep(struct task_desc
*task
, u64 timestamp
,
301 u64 task_state __used
)
303 struct sched_atom
*event
= get_new_event(task
, timestamp
);
305 event
->type
= SCHED_EVENT_SLEEP
;
310 static struct task_desc
*register_pid(unsigned long pid
, const char *comm
)
312 struct task_desc
*task
;
314 BUG_ON(pid
>= MAX_PID
);
316 task
= pid_to_task
[pid
];
321 task
= zalloc(sizeof(*task
));
324 strcpy(task
->comm
, comm
);
326 * every task starts in sleeping state - this gets ignored
327 * if there's no wakeup pointing to this sleep state:
329 add_sched_event_sleep(task
, 0, 0);
331 pid_to_task
[pid
] = task
;
333 tasks
= realloc(tasks
, nr_tasks
*sizeof(struct task_task
*));
335 tasks
[task
->nr
] = task
;
338 printf("registered task #%ld, PID %ld (%s)\n", nr_tasks
, pid
, comm
);
344 static void print_task_traces(void)
346 struct task_desc
*task
;
349 for (i
= 0; i
< nr_tasks
; i
++) {
351 printf("task %6ld (%20s:%10ld), nr_events: %ld\n",
352 task
->nr
, task
->comm
, task
->pid
, task
->nr_events
);
356 static void add_cross_task_wakeups(void)
358 struct task_desc
*task1
, *task2
;
361 for (i
= 0; i
< nr_tasks
; i
++) {
367 add_sched_event_wakeup(task1
, 0, task2
);
372 process_sched_event(struct task_desc
*this_task __used
, struct sched_atom
*atom
)
379 delta
= start_time
+ atom
->timestamp
- now
;
381 switch (atom
->type
) {
382 case SCHED_EVENT_RUN
:
383 burn_nsecs(atom
->duration
);
385 case SCHED_EVENT_SLEEP
:
387 ret
= sem_wait(atom
->wait_sem
);
390 case SCHED_EVENT_WAKEUP
:
392 ret
= sem_post(atom
->wait_sem
);
395 case SCHED_EVENT_MIGRATION
:
402 static u64
get_cpu_usage_nsec_parent(void)
408 err
= getrusage(RUSAGE_SELF
, &ru
);
411 sum
= ru
.ru_utime
.tv_sec
*1e9
+ ru
.ru_utime
.tv_usec
*1e3
;
412 sum
+= ru
.ru_stime
.tv_sec
*1e9
+ ru
.ru_stime
.tv_usec
*1e3
;
417 static int self_open_counters(void)
419 struct perf_event_attr attr
;
422 memset(&attr
, 0, sizeof(attr
));
424 attr
.type
= PERF_TYPE_SOFTWARE
;
425 attr
.config
= PERF_COUNT_SW_TASK_CLOCK
;
427 fd
= sys_perf_event_open(&attr
, 0, -1, -1, 0);
430 die("Error: sys_perf_event_open() syscall returned"
431 "with %d (%s)\n", fd
, strerror(errno
));
435 static u64
get_cpu_usage_nsec_self(int fd
)
440 ret
= read(fd
, &runtime
, sizeof(runtime
));
441 BUG_ON(ret
!= sizeof(runtime
));
446 static void *thread_func(void *ctx
)
448 struct task_desc
*this_task
= ctx
;
449 u64 cpu_usage_0
, cpu_usage_1
;
450 unsigned long i
, ret
;
454 sprintf(comm2
, ":%s", this_task
->comm
);
455 prctl(PR_SET_NAME
, comm2
);
456 fd
= self_open_counters();
459 ret
= sem_post(&this_task
->ready_for_work
);
461 ret
= pthread_mutex_lock(&start_work_mutex
);
463 ret
= pthread_mutex_unlock(&start_work_mutex
);
466 cpu_usage_0
= get_cpu_usage_nsec_self(fd
);
468 for (i
= 0; i
< this_task
->nr_events
; i
++) {
469 this_task
->curr_event
= i
;
470 process_sched_event(this_task
, this_task
->atoms
[i
]);
473 cpu_usage_1
= get_cpu_usage_nsec_self(fd
);
474 this_task
->cpu_usage
= cpu_usage_1
- cpu_usage_0
;
475 ret
= sem_post(&this_task
->work_done_sem
);
478 ret
= pthread_mutex_lock(&work_done_wait_mutex
);
480 ret
= pthread_mutex_unlock(&work_done_wait_mutex
);
486 static void create_tasks(void)
488 struct task_desc
*task
;
493 err
= pthread_attr_init(&attr
);
495 err
= pthread_attr_setstacksize(&attr
, (size_t)(16*1024));
497 err
= pthread_mutex_lock(&start_work_mutex
);
499 err
= pthread_mutex_lock(&work_done_wait_mutex
);
501 for (i
= 0; i
< nr_tasks
; i
++) {
503 sem_init(&task
->sleep_sem
, 0, 0);
504 sem_init(&task
->ready_for_work
, 0, 0);
505 sem_init(&task
->work_done_sem
, 0, 0);
506 task
->curr_event
= 0;
507 err
= pthread_create(&task
->thread
, &attr
, thread_func
, task
);
512 static void wait_for_tasks(void)
514 u64 cpu_usage_0
, cpu_usage_1
;
515 struct task_desc
*task
;
516 unsigned long i
, ret
;
518 start_time
= get_nsecs();
520 pthread_mutex_unlock(&work_done_wait_mutex
);
522 for (i
= 0; i
< nr_tasks
; i
++) {
524 ret
= sem_wait(&task
->ready_for_work
);
526 sem_init(&task
->ready_for_work
, 0, 0);
528 ret
= pthread_mutex_lock(&work_done_wait_mutex
);
531 cpu_usage_0
= get_cpu_usage_nsec_parent();
533 pthread_mutex_unlock(&start_work_mutex
);
535 for (i
= 0; i
< nr_tasks
; i
++) {
537 ret
= sem_wait(&task
->work_done_sem
);
539 sem_init(&task
->work_done_sem
, 0, 0);
540 cpu_usage
+= task
->cpu_usage
;
544 cpu_usage_1
= get_cpu_usage_nsec_parent();
545 if (!runavg_cpu_usage
)
546 runavg_cpu_usage
= cpu_usage
;
547 runavg_cpu_usage
= (runavg_cpu_usage
*9 + cpu_usage
)/10;
549 parent_cpu_usage
= cpu_usage_1
- cpu_usage_0
;
550 if (!runavg_parent_cpu_usage
)
551 runavg_parent_cpu_usage
= parent_cpu_usage
;
552 runavg_parent_cpu_usage
= (runavg_parent_cpu_usage
*9 +
553 parent_cpu_usage
)/10;
555 ret
= pthread_mutex_lock(&start_work_mutex
);
558 for (i
= 0; i
< nr_tasks
; i
++) {
560 sem_init(&task
->sleep_sem
, 0, 0);
561 task
->curr_event
= 0;
565 static void run_one_test(void)
567 u64 T0
, T1
, delta
, avg_delta
, fluct
, std_dev
;
574 sum_runtime
+= delta
;
577 avg_delta
= sum_runtime
/ nr_runs
;
578 if (delta
< avg_delta
)
579 fluct
= avg_delta
- delta
;
581 fluct
= delta
- avg_delta
;
583 std_dev
= sum_fluct
/ nr_runs
/ sqrt(nr_runs
);
586 run_avg
= (run_avg
*9 + delta
)/10;
588 printf("#%-3ld: %0.3f, ",
589 nr_runs
, (double)delta
/1000000.0);
591 printf("ravg: %0.2f, ",
592 (double)run_avg
/1e6
);
594 printf("cpu: %0.2f / %0.2f",
595 (double)cpu_usage
/1e6
, (double)runavg_cpu_usage
/1e6
);
599 * rusage statistics done by the parent, these are less
600 * accurate than the sum_exec_runtime based statistics:
602 printf(" [%0.2f / %0.2f]",
603 (double)parent_cpu_usage
/1e6
,
604 (double)runavg_parent_cpu_usage
/1e6
);
609 if (nr_sleep_corrections
)
610 printf(" (%ld sleep corrections)\n", nr_sleep_corrections
);
611 nr_sleep_corrections
= 0;
614 static void test_calibrations(void)
622 printf("the run test took %Ld nsecs\n", T1
-T0
);
628 printf("the sleep test took %Ld nsecs\n", T1
-T0
);
631 #define FILL_FIELD(ptr, field, event, data) \
632 ptr.field = (typeof(ptr.field)) raw_field_value(event, #field, data)
634 #define FILL_ARRAY(ptr, array, event, data) \
636 void *__array = raw_field_ptr(event, #array, data); \
637 memcpy(ptr.array, __array, sizeof(ptr.array)); \
640 #define FILL_COMMON_FIELDS(ptr, event, data) \
642 FILL_FIELD(ptr, common_type, event, data); \
643 FILL_FIELD(ptr, common_flags, event, data); \
644 FILL_FIELD(ptr, common_preempt_count, event, data); \
645 FILL_FIELD(ptr, common_pid, event, data); \
646 FILL_FIELD(ptr, common_tgid, event, data); \
651 struct trace_switch_event
{
656 u8 common_preempt_count
;
669 struct trace_runtime_event
{
674 u8 common_preempt_count
;
684 struct trace_wakeup_event
{
689 u8 common_preempt_count
;
701 struct trace_fork_event
{
706 u8 common_preempt_count
;
710 char parent_comm
[16];
716 struct trace_migrate_task_event
{
721 u8 common_preempt_count
;
732 struct trace_sched_handler
{
733 void (*switch_event
)(struct trace_switch_event
*,
737 struct thread
*thread
);
739 void (*runtime_event
)(struct trace_runtime_event
*,
743 struct thread
*thread
);
745 void (*wakeup_event
)(struct trace_wakeup_event
*,
749 struct thread
*thread
);
751 void (*fork_event
)(struct trace_fork_event
*,
755 struct thread
*thread
);
757 void (*migrate_task_event
)(struct trace_migrate_task_event
*,
761 struct thread
*thread
);
766 replay_wakeup_event(struct trace_wakeup_event
*wakeup_event
,
769 u64 timestamp __used
,
770 struct thread
*thread __used
)
772 struct task_desc
*waker
, *wakee
;
775 printf("sched_wakeup event %p\n", event
);
777 printf(" ... pid %d woke up %s/%d\n",
778 wakeup_event
->common_pid
,
783 waker
= register_pid(wakeup_event
->common_pid
, "<unknown>");
784 wakee
= register_pid(wakeup_event
->pid
, wakeup_event
->comm
);
786 add_sched_event_wakeup(waker
, timestamp
, wakee
);
789 static u64 cpu_last_switched
[MAX_CPUS
];
792 replay_switch_event(struct trace_switch_event
*switch_event
,
796 struct thread
*thread __used
)
798 struct task_desc
*prev
, *next
;
803 printf("sched_switch event %p\n", event
);
805 if (cpu
>= MAX_CPUS
|| cpu
< 0)
808 timestamp0
= cpu_last_switched
[cpu
];
810 delta
= timestamp
- timestamp0
;
815 die("hm, delta: %Ld < 0 ?\n", delta
);
818 printf(" ... switch from %s/%d to %s/%d [ran %Ld nsecs]\n",
819 switch_event
->prev_comm
, switch_event
->prev_pid
,
820 switch_event
->next_comm
, switch_event
->next_pid
,
824 prev
= register_pid(switch_event
->prev_pid
, switch_event
->prev_comm
);
825 next
= register_pid(switch_event
->next_pid
, switch_event
->next_comm
);
827 cpu_last_switched
[cpu
] = timestamp
;
829 add_sched_event_run(prev
, timestamp
, delta
);
830 add_sched_event_sleep(prev
, timestamp
, switch_event
->prev_state
);
835 replay_fork_event(struct trace_fork_event
*fork_event
,
838 u64 timestamp __used
,
839 struct thread
*thread __used
)
842 printf("sched_fork event %p\n", event
);
843 printf("... parent: %s/%d\n", fork_event
->parent_comm
, fork_event
->parent_pid
);
844 printf("... child: %s/%d\n", fork_event
->child_comm
, fork_event
->child_pid
);
846 register_pid(fork_event
->parent_pid
, fork_event
->parent_comm
);
847 register_pid(fork_event
->child_pid
, fork_event
->child_comm
);
850 static struct trace_sched_handler replay_ops
= {
851 .wakeup_event
= replay_wakeup_event
,
852 .switch_event
= replay_switch_event
,
853 .fork_event
= replay_fork_event
,
856 struct sort_dimension
{
859 struct list_head list
;
862 static LIST_HEAD(cmp_pid
);
865 thread_lat_cmp(struct list_head
*list
, struct work_atoms
*l
, struct work_atoms
*r
)
867 struct sort_dimension
*sort
;
870 BUG_ON(list_empty(list
));
872 list_for_each_entry(sort
, list
, list
) {
873 ret
= sort
->cmp(l
, r
);
881 static struct work_atoms
*
882 thread_atoms_search(struct rb_root
*root
, struct thread
*thread
,
883 struct list_head
*sort_list
)
885 struct rb_node
*node
= root
->rb_node
;
886 struct work_atoms key
= { .thread
= thread
};
889 struct work_atoms
*atoms
;
892 atoms
= container_of(node
, struct work_atoms
, node
);
894 cmp
= thread_lat_cmp(sort_list
, &key
, atoms
);
896 node
= node
->rb_left
;
898 node
= node
->rb_right
;
900 BUG_ON(thread
!= atoms
->thread
);
908 __thread_latency_insert(struct rb_root
*root
, struct work_atoms
*data
,
909 struct list_head
*sort_list
)
911 struct rb_node
**new = &(root
->rb_node
), *parent
= NULL
;
914 struct work_atoms
*this;
917 this = container_of(*new, struct work_atoms
, node
);
920 cmp
= thread_lat_cmp(sort_list
, data
, this);
923 new = &((*new)->rb_left
);
925 new = &((*new)->rb_right
);
928 rb_link_node(&data
->node
, parent
, new);
929 rb_insert_color(&data
->node
, root
);
932 static void thread_atoms_insert(struct thread
*thread
)
934 struct work_atoms
*atoms
= zalloc(sizeof(*atoms
));
938 atoms
->thread
= thread
;
939 INIT_LIST_HEAD(&atoms
->work_list
);
940 __thread_latency_insert(&atom_root
, atoms
, &cmp_pid
);
944 latency_fork_event(struct trace_fork_event
*fork_event __used
,
945 struct event
*event __used
,
947 u64 timestamp __used
,
948 struct thread
*thread __used
)
950 /* should insert the newcomer */
954 static char sched_out_state(struct trace_switch_event
*switch_event
)
956 const char *str
= TASK_STATE_TO_CHAR_STR
;
958 return str
[switch_event
->prev_state
];
962 add_sched_out_event(struct work_atoms
*atoms
,
966 struct work_atom
*atom
= zalloc(sizeof(*atom
));
970 atom
->sched_out_time
= timestamp
;
972 if (run_state
== 'R') {
973 atom
->state
= THREAD_WAIT_CPU
;
974 atom
->wake_up_time
= atom
->sched_out_time
;
977 list_add_tail(&atom
->list
, &atoms
->work_list
);
981 add_runtime_event(struct work_atoms
*atoms
, u64 delta
, u64 timestamp __used
)
983 struct work_atom
*atom
;
985 BUG_ON(list_empty(&atoms
->work_list
));
987 atom
= list_entry(atoms
->work_list
.prev
, struct work_atom
, list
);
989 atom
->runtime
+= delta
;
990 atoms
->total_runtime
+= delta
;
994 add_sched_in_event(struct work_atoms
*atoms
, u64 timestamp
)
996 struct work_atom
*atom
;
999 if (list_empty(&atoms
->work_list
))
1002 atom
= list_entry(atoms
->work_list
.prev
, struct work_atom
, list
);
1004 if (atom
->state
!= THREAD_WAIT_CPU
)
1007 if (timestamp
< atom
->wake_up_time
) {
1008 atom
->state
= THREAD_IGNORE
;
1012 atom
->state
= THREAD_SCHED_IN
;
1013 atom
->sched_in_time
= timestamp
;
1015 delta
= atom
->sched_in_time
- atom
->wake_up_time
;
1016 atoms
->total_lat
+= delta
;
1017 if (delta
> atoms
->max_lat
) {
1018 atoms
->max_lat
= delta
;
1019 atoms
->max_lat_at
= timestamp
;
1025 latency_switch_event(struct trace_switch_event
*switch_event
,
1026 struct event
*event __used
,
1029 struct thread
*thread __used
)
1031 struct work_atoms
*out_events
, *in_events
;
1032 struct thread
*sched_out
, *sched_in
;
1036 BUG_ON(cpu
>= MAX_CPUS
|| cpu
< 0);
1038 timestamp0
= cpu_last_switched
[cpu
];
1039 cpu_last_switched
[cpu
] = timestamp
;
1041 delta
= timestamp
- timestamp0
;
1046 die("hm, delta: %Ld < 0 ?\n", delta
);
1049 sched_out
= threads__findnew(switch_event
->prev_pid
);
1050 sched_in
= threads__findnew(switch_event
->next_pid
);
1052 out_events
= thread_atoms_search(&atom_root
, sched_out
, &cmp_pid
);
1054 thread_atoms_insert(sched_out
);
1055 out_events
= thread_atoms_search(&atom_root
, sched_out
, &cmp_pid
);
1057 die("out-event: Internal tree error");
1059 add_sched_out_event(out_events
, sched_out_state(switch_event
), timestamp
);
1061 in_events
= thread_atoms_search(&atom_root
, sched_in
, &cmp_pid
);
1063 thread_atoms_insert(sched_in
);
1064 in_events
= thread_atoms_search(&atom_root
, sched_in
, &cmp_pid
);
1066 die("in-event: Internal tree error");
1068 * Take came in we have not heard about yet,
1069 * add in an initial atom in runnable state:
1071 add_sched_out_event(in_events
, 'R', timestamp
);
1073 add_sched_in_event(in_events
, timestamp
);
1077 latency_runtime_event(struct trace_runtime_event
*runtime_event
,
1078 struct event
*event __used
,
1081 struct thread
*this_thread __used
)
1083 struct thread
*thread
= threads__findnew(runtime_event
->pid
);
1084 struct work_atoms
*atoms
= thread_atoms_search(&atom_root
, thread
, &cmp_pid
);
1086 BUG_ON(cpu
>= MAX_CPUS
|| cpu
< 0);
1088 thread_atoms_insert(thread
);
1089 atoms
= thread_atoms_search(&atom_root
, thread
, &cmp_pid
);
1091 die("in-event: Internal tree error");
1092 add_sched_out_event(atoms
, 'R', timestamp
);
1095 add_runtime_event(atoms
, runtime_event
->runtime
, timestamp
);
1099 latency_wakeup_event(struct trace_wakeup_event
*wakeup_event
,
1100 struct event
*__event __used
,
1103 struct thread
*thread __used
)
1105 struct work_atoms
*atoms
;
1106 struct work_atom
*atom
;
1107 struct thread
*wakee
;
1109 /* Note for later, it may be interesting to observe the failing cases */
1110 if (!wakeup_event
->success
)
1113 wakee
= threads__findnew(wakeup_event
->pid
);
1114 atoms
= thread_atoms_search(&atom_root
, wakee
, &cmp_pid
);
1116 thread_atoms_insert(wakee
);
1117 atoms
= thread_atoms_search(&atom_root
, wakee
, &cmp_pid
);
1119 die("wakeup-event: Internal tree error");
1120 add_sched_out_event(atoms
, 'S', timestamp
);
1123 BUG_ON(list_empty(&atoms
->work_list
));
1125 atom
= list_entry(atoms
->work_list
.prev
, struct work_atom
, list
);
1128 * You WILL be missing events if you've recorded only
1129 * one CPU, or are only looking at only one, so don't
1130 * make useless noise.
1132 if (profile_cpu
== -1 && atom
->state
!= THREAD_SLEEPING
)
1133 nr_state_machine_bugs
++;
1136 if (atom
->sched_out_time
> timestamp
) {
1137 nr_unordered_timestamps
++;
1141 atom
->state
= THREAD_WAIT_CPU
;
1142 atom
->wake_up_time
= timestamp
;
1146 latency_migrate_task_event(struct trace_migrate_task_event
*migrate_task_event
,
1147 struct event
*__event __used
,
1150 struct thread
*thread __used
)
1152 struct work_atoms
*atoms
;
1153 struct work_atom
*atom
;
1154 struct thread
*migrant
;
1157 * Only need to worry about migration when profiling one CPU.
1159 if (profile_cpu
== -1)
1162 migrant
= threads__findnew(migrate_task_event
->pid
);
1163 atoms
= thread_atoms_search(&atom_root
, migrant
, &cmp_pid
);
1165 thread_atoms_insert(migrant
);
1166 register_pid(migrant
->pid
, migrant
->comm
);
1167 atoms
= thread_atoms_search(&atom_root
, migrant
, &cmp_pid
);
1169 die("migration-event: Internal tree error");
1170 add_sched_out_event(atoms
, 'R', timestamp
);
1173 BUG_ON(list_empty(&atoms
->work_list
));
1175 atom
= list_entry(atoms
->work_list
.prev
, struct work_atom
, list
);
1176 atom
->sched_in_time
= atom
->sched_out_time
= atom
->wake_up_time
= timestamp
;
1180 if (atom
->sched_out_time
> timestamp
)
1181 nr_unordered_timestamps
++;
1184 static struct trace_sched_handler lat_ops
= {
1185 .wakeup_event
= latency_wakeup_event
,
1186 .switch_event
= latency_switch_event
,
1187 .runtime_event
= latency_runtime_event
,
1188 .fork_event
= latency_fork_event
,
1189 .migrate_task_event
= latency_migrate_task_event
,
1192 static void output_lat_thread(struct work_atoms
*work_list
)
1198 if (!work_list
->nb_atoms
)
1201 * Ignore idle threads:
1203 if (!strcmp(work_list
->thread
->comm
, "swapper"))
1206 all_runtime
+= work_list
->total_runtime
;
1207 all_count
+= work_list
->nb_atoms
;
1209 ret
= printf(" %s:%d ", work_list
->thread
->comm
, work_list
->thread
->pid
);
1211 for (i
= 0; i
< 24 - ret
; i
++)
1214 avg
= work_list
->total_lat
/ work_list
->nb_atoms
;
1216 printf("|%11.3f ms |%9llu | avg:%9.3f ms | max:%9.3f ms | max at: %9.6f s\n",
1217 (double)work_list
->total_runtime
/ 1e6
,
1218 work_list
->nb_atoms
, (double)avg
/ 1e6
,
1219 (double)work_list
->max_lat
/ 1e6
,
1220 (double)work_list
->max_lat_at
/ 1e9
);
1223 static int pid_cmp(struct work_atoms
*l
, struct work_atoms
*r
)
1225 if (l
->thread
->pid
< r
->thread
->pid
)
1227 if (l
->thread
->pid
> r
->thread
->pid
)
1233 static struct sort_dimension pid_sort_dimension
= {
1238 static int avg_cmp(struct work_atoms
*l
, struct work_atoms
*r
)
1248 avgl
= l
->total_lat
/ l
->nb_atoms
;
1249 avgr
= r
->total_lat
/ r
->nb_atoms
;
1259 static struct sort_dimension avg_sort_dimension
= {
1264 static int max_cmp(struct work_atoms
*l
, struct work_atoms
*r
)
1266 if (l
->max_lat
< r
->max_lat
)
1268 if (l
->max_lat
> r
->max_lat
)
1274 static struct sort_dimension max_sort_dimension
= {
1279 static int switch_cmp(struct work_atoms
*l
, struct work_atoms
*r
)
1281 if (l
->nb_atoms
< r
->nb_atoms
)
1283 if (l
->nb_atoms
> r
->nb_atoms
)
1289 static struct sort_dimension switch_sort_dimension
= {
1294 static int runtime_cmp(struct work_atoms
*l
, struct work_atoms
*r
)
1296 if (l
->total_runtime
< r
->total_runtime
)
1298 if (l
->total_runtime
> r
->total_runtime
)
1304 static struct sort_dimension runtime_sort_dimension
= {
1309 static struct sort_dimension
*available_sorts
[] = {
1310 &pid_sort_dimension
,
1311 &avg_sort_dimension
,
1312 &max_sort_dimension
,
1313 &switch_sort_dimension
,
1314 &runtime_sort_dimension
,
1317 #define NB_AVAILABLE_SORTS (int)(sizeof(available_sorts) / sizeof(struct sort_dimension *))
1319 static LIST_HEAD(sort_list
);
1321 static int sort_dimension__add(const char *tok
, struct list_head
*list
)
1325 for (i
= 0; i
< NB_AVAILABLE_SORTS
; i
++) {
1326 if (!strcmp(available_sorts
[i
]->name
, tok
)) {
1327 list_add_tail(&available_sorts
[i
]->list
, list
);
1336 static void setup_sorting(void);
1338 static void sort_lat(void)
1340 struct rb_node
*node
;
1343 struct work_atoms
*data
;
1344 node
= rb_first(&atom_root
);
1348 rb_erase(node
, &atom_root
);
1349 data
= rb_entry(node
, struct work_atoms
, node
);
1350 __thread_latency_insert(&sorted_atom_root
, data
, &sort_list
);
1354 static struct trace_sched_handler
*trace_handler
;
1357 process_sched_wakeup_event(void *data
,
1358 struct event
*event
,
1360 u64 timestamp __used
,
1361 struct thread
*thread __used
)
1363 struct trace_wakeup_event wakeup_event
;
1365 FILL_COMMON_FIELDS(wakeup_event
, event
, data
);
1367 FILL_ARRAY(wakeup_event
, comm
, event
, data
);
1368 FILL_FIELD(wakeup_event
, pid
, event
, data
);
1369 FILL_FIELD(wakeup_event
, prio
, event
, data
);
1370 FILL_FIELD(wakeup_event
, success
, event
, data
);
1371 FILL_FIELD(wakeup_event
, cpu
, event
, data
);
1373 if (trace_handler
->wakeup_event
)
1374 trace_handler
->wakeup_event(&wakeup_event
, event
, cpu
, timestamp
, thread
);
1378 * Track the current task - that way we can know whether there's any
1379 * weird events, such as a task being switched away that is not current.
1383 static u32 curr_pid
[MAX_CPUS
] = { [0 ... MAX_CPUS
-1] = -1 };
1385 static struct thread
*curr_thread
[MAX_CPUS
];
1387 static char next_shortname1
= 'A';
1388 static char next_shortname2
= '0';
1391 map_switch_event(struct trace_switch_event
*switch_event
,
1392 struct event
*event __used
,
1395 struct thread
*thread __used
)
1397 struct thread
*sched_out
, *sched_in
;
1403 BUG_ON(this_cpu
>= MAX_CPUS
|| this_cpu
< 0);
1405 if (this_cpu
> max_cpu
)
1408 timestamp0
= cpu_last_switched
[this_cpu
];
1409 cpu_last_switched
[this_cpu
] = timestamp
;
1411 delta
= timestamp
- timestamp0
;
1416 die("hm, delta: %Ld < 0 ?\n", delta
);
1419 sched_out
= threads__findnew(switch_event
->prev_pid
);
1420 sched_in
= threads__findnew(switch_event
->next_pid
);
1422 curr_thread
[this_cpu
] = sched_in
;
1427 if (!sched_in
->shortname
[0]) {
1428 sched_in
->shortname
[0] = next_shortname1
;
1429 sched_in
->shortname
[1] = next_shortname2
;
1431 if (next_shortname1
< 'Z') {
1434 next_shortname1
='A';
1435 if (next_shortname2
< '9') {
1438 next_shortname2
='0';
1444 for (cpu
= 0; cpu
<= max_cpu
; cpu
++) {
1445 if (cpu
!= this_cpu
)
1450 if (curr_thread
[cpu
]) {
1451 if (curr_thread
[cpu
]->pid
)
1452 printf("%2s ", curr_thread
[cpu
]->shortname
);
1459 printf(" %12.6f secs ", (double)timestamp
/1e9
);
1460 if (new_shortname
) {
1461 printf("%s => %s:%d\n",
1462 sched_in
->shortname
, sched_in
->comm
, sched_in
->pid
);
1470 process_sched_switch_event(void *data
,
1471 struct event
*event
,
1473 u64 timestamp __used
,
1474 struct thread
*thread __used
)
1476 struct trace_switch_event switch_event
;
1478 FILL_COMMON_FIELDS(switch_event
, event
, data
);
1480 FILL_ARRAY(switch_event
, prev_comm
, event
, data
);
1481 FILL_FIELD(switch_event
, prev_pid
, event
, data
);
1482 FILL_FIELD(switch_event
, prev_prio
, event
, data
);
1483 FILL_FIELD(switch_event
, prev_state
, event
, data
);
1484 FILL_ARRAY(switch_event
, next_comm
, event
, data
);
1485 FILL_FIELD(switch_event
, next_pid
, event
, data
);
1486 FILL_FIELD(switch_event
, next_prio
, event
, data
);
1488 if (curr_pid
[this_cpu
] != (u32
)-1) {
1490 * Are we trying to switch away a PID that is
1493 if (curr_pid
[this_cpu
] != switch_event
.prev_pid
)
1494 nr_context_switch_bugs
++;
1496 if (trace_handler
->switch_event
)
1497 trace_handler
->switch_event(&switch_event
, event
, this_cpu
, timestamp
, thread
);
1499 curr_pid
[this_cpu
] = switch_event
.next_pid
;
1503 process_sched_runtime_event(void *data
,
1504 struct event
*event
,
1506 u64 timestamp __used
,
1507 struct thread
*thread __used
)
1509 struct trace_runtime_event runtime_event
;
1511 FILL_ARRAY(runtime_event
, comm
, event
, data
);
1512 FILL_FIELD(runtime_event
, pid
, event
, data
);
1513 FILL_FIELD(runtime_event
, runtime
, event
, data
);
1514 FILL_FIELD(runtime_event
, vruntime
, event
, data
);
1516 if (trace_handler
->runtime_event
)
1517 trace_handler
->runtime_event(&runtime_event
, event
, cpu
, timestamp
, thread
);
1521 process_sched_fork_event(void *data
,
1522 struct event
*event
,
1524 u64 timestamp __used
,
1525 struct thread
*thread __used
)
1527 struct trace_fork_event fork_event
;
1529 FILL_COMMON_FIELDS(fork_event
, event
, data
);
1531 FILL_ARRAY(fork_event
, parent_comm
, event
, data
);
1532 FILL_FIELD(fork_event
, parent_pid
, event
, data
);
1533 FILL_ARRAY(fork_event
, child_comm
, event
, data
);
1534 FILL_FIELD(fork_event
, child_pid
, event
, data
);
1536 if (trace_handler
->fork_event
)
1537 trace_handler
->fork_event(&fork_event
, event
, cpu
, timestamp
, thread
);
1541 process_sched_exit_event(struct event
*event
,
1543 u64 timestamp __used
,
1544 struct thread
*thread __used
)
1547 printf("sched_exit event %p\n", event
);
1551 process_sched_migrate_task_event(void *data
,
1552 struct event
*event
,
1554 u64 timestamp __used
,
1555 struct thread
*thread __used
)
1557 struct trace_migrate_task_event migrate_task_event
;
1559 FILL_COMMON_FIELDS(migrate_task_event
, event
, data
);
1561 FILL_ARRAY(migrate_task_event
, comm
, event
, data
);
1562 FILL_FIELD(migrate_task_event
, pid
, event
, data
);
1563 FILL_FIELD(migrate_task_event
, prio
, event
, data
);
1564 FILL_FIELD(migrate_task_event
, cpu
, event
, data
);
1566 if (trace_handler
->migrate_task_event
)
1567 trace_handler
->migrate_task_event(&migrate_task_event
, event
, cpu
, timestamp
, thread
);
1571 process_raw_event(event_t
*raw_event __used
, void *data
,
1572 int cpu
, u64 timestamp
, struct thread
*thread
)
1574 struct event
*event
;
1578 type
= trace_parse_common_type(data
);
1579 event
= trace_find_event(type
);
1581 if (!strcmp(event
->name
, "sched_switch"))
1582 process_sched_switch_event(data
, event
, cpu
, timestamp
, thread
);
1583 if (!strcmp(event
->name
, "sched_stat_runtime"))
1584 process_sched_runtime_event(data
, event
, cpu
, timestamp
, thread
);
1585 if (!strcmp(event
->name
, "sched_wakeup"))
1586 process_sched_wakeup_event(data
, event
, cpu
, timestamp
, thread
);
1587 if (!strcmp(event
->name
, "sched_wakeup_new"))
1588 process_sched_wakeup_event(data
, event
, cpu
, timestamp
, thread
);
1589 if (!strcmp(event
->name
, "sched_process_fork"))
1590 process_sched_fork_event(data
, event
, cpu
, timestamp
, thread
);
1591 if (!strcmp(event
->name
, "sched_process_exit"))
1592 process_sched_exit_event(event
, cpu
, timestamp
, thread
);
1593 if (!strcmp(event
->name
, "sched_migrate_task"))
1594 process_sched_migrate_task_event(data
, event
, cpu
, timestamp
, thread
);
1597 static int process_sample_event(event_t
*event
)
1599 struct sample_data data
;
1600 struct thread
*thread
;
1602 if (!(sample_type
& PERF_SAMPLE_RAW
))
1605 memset(&data
, 0, sizeof(data
));
1610 event__parse_sample(event
, sample_type
, &data
);
1612 dump_printf("(IP, %d): %d/%d: %p period: %Ld\n",
1615 (void *)(long)data
.ip
,
1616 (long long)data
.period
);
1618 thread
= threads__findnew(data
.pid
);
1619 if (thread
== NULL
) {
1620 pr_debug("problem processing %d event, skipping it.\n",
1621 event
->header
.type
);
1625 dump_printf(" ... thread: %s:%d\n", thread
->comm
, thread
->pid
);
1627 if (profile_cpu
!= -1 && profile_cpu
!= (int)data
.cpu
)
1630 process_raw_event(event
, data
.raw_data
, data
.cpu
, data
.time
, thread
);
1635 static int process_lost_event(event_t
*event __used
)
1638 nr_lost_events
+= event
->lost
.lost
;
1643 static int sample_type_check(u64 type
)
1647 if (!(sample_type
& PERF_SAMPLE_RAW
)) {
1649 "No trace sample to read. Did you call perf record "
1657 static struct perf_file_handler file_handler
= {
1658 .process_sample_event
= process_sample_event
,
1659 .process_comm_event
= event__process_comm
,
1660 .process_lost_event
= process_lost_event
,
1661 .sample_type_check
= sample_type_check
,
1664 static int read_events(void)
1667 struct perf_session
*session
= perf_session__new(input_name
, O_RDONLY
, 0);
1669 if (session
== NULL
)
1672 register_idle_thread();
1673 register_perf_file_handler(&file_handler
);
1675 err
= perf_session__process_events(session
, 0, &event__cwdlen
, &event__cwd
);
1676 perf_session__delete(session
);
1680 static void print_bad_events(void)
1682 if (nr_unordered_timestamps
&& nr_timestamps
) {
1683 printf(" INFO: %.3f%% unordered timestamps (%ld out of %ld)\n",
1684 (double)nr_unordered_timestamps
/(double)nr_timestamps
*100.0,
1685 nr_unordered_timestamps
, nr_timestamps
);
1687 if (nr_lost_events
&& nr_events
) {
1688 printf(" INFO: %.3f%% lost events (%ld out of %ld, in %ld chunks)\n",
1689 (double)nr_lost_events
/(double)nr_events
*100.0,
1690 nr_lost_events
, nr_events
, nr_lost_chunks
);
1692 if (nr_state_machine_bugs
&& nr_timestamps
) {
1693 printf(" INFO: %.3f%% state machine bugs (%ld out of %ld)",
1694 (double)nr_state_machine_bugs
/(double)nr_timestamps
*100.0,
1695 nr_state_machine_bugs
, nr_timestamps
);
1697 printf(" (due to lost events?)");
1700 if (nr_context_switch_bugs
&& nr_timestamps
) {
1701 printf(" INFO: %.3f%% context switch bugs (%ld out of %ld)",
1702 (double)nr_context_switch_bugs
/(double)nr_timestamps
*100.0,
1703 nr_context_switch_bugs
, nr_timestamps
);
1705 printf(" (due to lost events?)");
1710 static void __cmd_lat(void)
1712 struct rb_node
*next
;
1718 printf("\n ---------------------------------------------------------------------------------------------------------------\n");
1719 printf(" Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | Maximum delay at |\n");
1720 printf(" ---------------------------------------------------------------------------------------------------------------\n");
1722 next
= rb_first(&sorted_atom_root
);
1725 struct work_atoms
*work_list
;
1727 work_list
= rb_entry(next
, struct work_atoms
, node
);
1728 output_lat_thread(work_list
);
1729 next
= rb_next(next
);
1732 printf(" -----------------------------------------------------------------------------------------\n");
1733 printf(" TOTAL: |%11.3f ms |%9Ld |\n",
1734 (double)all_runtime
/1e6
, all_count
);
1736 printf(" ---------------------------------------------------\n");
1743 static struct trace_sched_handler map_ops
= {
1744 .wakeup_event
= NULL
,
1745 .switch_event
= map_switch_event
,
1746 .runtime_event
= NULL
,
1750 static void __cmd_map(void)
1752 max_cpu
= sysconf(_SC_NPROCESSORS_CONF
);
1759 static void __cmd_replay(void)
1763 calibrate_run_measurement_overhead();
1764 calibrate_sleep_measurement_overhead();
1766 test_calibrations();
1770 printf("nr_run_events: %ld\n", nr_run_events
);
1771 printf("nr_sleep_events: %ld\n", nr_sleep_events
);
1772 printf("nr_wakeup_events: %ld\n", nr_wakeup_events
);
1774 if (targetless_wakeups
)
1775 printf("target-less wakeups: %ld\n", targetless_wakeups
);
1776 if (multitarget_wakeups
)
1777 printf("multi-target wakeups: %ld\n", multitarget_wakeups
);
1778 if (nr_run_events_optimized
)
1779 printf("run atoms optimized: %ld\n",
1780 nr_run_events_optimized
);
1782 print_task_traces();
1783 add_cross_task_wakeups();
1786 printf("------------------------------------------------------------\n");
1787 for (i
= 0; i
< replay_repeat
; i
++)
1792 static const char * const sched_usage
[] = {
1793 "perf sched [<options>] {record|latency|map|replay|trace}",
1797 static const struct option sched_options
[] = {
1798 OPT_STRING('i', "input", &input_name
, "file",
1800 OPT_BOOLEAN('v', "verbose", &verbose
,
1801 "be more verbose (show symbol address, etc)"),
1802 OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace
,
1803 "dump raw trace in ASCII"),
1807 static const char * const latency_usage
[] = {
1808 "perf sched latency [<options>]",
1812 static const struct option latency_options
[] = {
1813 OPT_STRING('s', "sort", &sort_order
, "key[,key2...]",
1814 "sort by key(s): runtime, switch, avg, max"),
1815 OPT_BOOLEAN('v', "verbose", &verbose
,
1816 "be more verbose (show symbol address, etc)"),
1817 OPT_INTEGER('C', "CPU", &profile_cpu
,
1818 "CPU to profile on"),
1819 OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace
,
1820 "dump raw trace in ASCII"),
1824 static const char * const replay_usage
[] = {
1825 "perf sched replay [<options>]",
1829 static const struct option replay_options
[] = {
1830 OPT_INTEGER('r', "repeat", &replay_repeat
,
1831 "repeat the workload replay N times (-1: infinite)"),
1832 OPT_BOOLEAN('v', "verbose", &verbose
,
1833 "be more verbose (show symbol address, etc)"),
1834 OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace
,
1835 "dump raw trace in ASCII"),
1839 static void setup_sorting(void)
1841 char *tmp
, *tok
, *str
= strdup(sort_order
);
1843 for (tok
= strtok_r(str
, ", ", &tmp
);
1844 tok
; tok
= strtok_r(NULL
, ", ", &tmp
)) {
1845 if (sort_dimension__add(tok
, &sort_list
) < 0) {
1846 error("Unknown --sort key: `%s'", tok
);
1847 usage_with_options(latency_usage
, latency_options
);
1853 sort_dimension__add("pid", &cmp_pid
);
1856 static const char *record_args
[] = {
1864 "-e", "sched:sched_switch:r",
1865 "-e", "sched:sched_stat_wait:r",
1866 "-e", "sched:sched_stat_sleep:r",
1867 "-e", "sched:sched_stat_iowait:r",
1868 "-e", "sched:sched_stat_runtime:r",
1869 "-e", "sched:sched_process_exit:r",
1870 "-e", "sched:sched_process_fork:r",
1871 "-e", "sched:sched_wakeup:r",
1872 "-e", "sched:sched_migrate_task:r",
1875 static int __cmd_record(int argc
, const char **argv
)
1877 unsigned int rec_argc
, i
, j
;
1878 const char **rec_argv
;
1880 rec_argc
= ARRAY_SIZE(record_args
) + argc
- 1;
1881 rec_argv
= calloc(rec_argc
+ 1, sizeof(char *));
1883 for (i
= 0; i
< ARRAY_SIZE(record_args
); i
++)
1884 rec_argv
[i
] = strdup(record_args
[i
]);
1886 for (j
= 1; j
< (unsigned int)argc
; j
++, i
++)
1887 rec_argv
[i
] = argv
[j
];
1889 BUG_ON(i
!= rec_argc
);
1891 return cmd_record(i
, rec_argv
, NULL
);
1894 int cmd_sched(int argc
, const char **argv
, const char *prefix __used
)
1896 argc
= parse_options(argc
, argv
, sched_options
, sched_usage
,
1897 PARSE_OPT_STOP_AT_NON_OPTION
);
1899 usage_with_options(sched_usage
, sched_options
);
1902 * Aliased to 'perf trace' for now:
1904 if (!strcmp(argv
[0], "trace"))
1905 return cmd_trace(argc
, argv
, prefix
);
1908 if (!strncmp(argv
[0], "rec", 3)) {
1909 return __cmd_record(argc
, argv
);
1910 } else if (!strncmp(argv
[0], "lat", 3)) {
1911 trace_handler
= &lat_ops
;
1913 argc
= parse_options(argc
, argv
, latency_options
, latency_usage
, 0);
1915 usage_with_options(latency_usage
, latency_options
);
1919 } else if (!strcmp(argv
[0], "map")) {
1920 trace_handler
= &map_ops
;
1923 } else if (!strncmp(argv
[0], "rep", 3)) {
1924 trace_handler
= &replay_ops
;
1926 argc
= parse_options(argc
, argv
, replay_options
, replay_usage
, 0);
1928 usage_with_options(replay_usage
, replay_options
);
1932 usage_with_options(sched_usage
, sched_options
);