diff options
-rw-r--r-- | tools/perf/builtin-sched.c | 842 | ||||
-rw-r--r-- | tools/perf/util/trace-event-parse.c | 16 | ||||
-rw-r--r-- | tools/perf/util/trace-event.h | 2 |
3 files changed, 827 insertions, 33 deletions
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c index 60228d9179ac..c66e6a321371 100644 --- a/tools/perf/builtin-sched.c +++ b/tools/perf/builtin-sched.c | |||
@@ -12,22 +12,770 @@ | |||
12 | #include "util/debug.h" | 12 | #include "util/debug.h" |
13 | 13 | ||
14 | #include "util/trace-event.h" | 14 | #include "util/trace-event.h" |
15 | #include <sys/types.h> | ||
15 | 16 | ||
16 | static char const *input_name = "perf.data"; | 17 | static char const *input_name = "perf.data"; |
17 | static int input; | 18 | static int input; |
18 | static unsigned long page_size; | 19 | static unsigned long page_size; |
19 | static unsigned long mmap_window = 32; | 20 | static unsigned long mmap_window = 32; |
20 | 21 | ||
21 | static unsigned long total = 0; | 22 | static unsigned long total_comm = 0; |
22 | static unsigned long total_comm = 0; | ||
23 | 23 | ||
24 | static struct rb_root threads; | 24 | static struct rb_root threads; |
25 | static struct thread *last_match; | 25 | static struct thread *last_match; |
26 | 26 | ||
27 | static struct perf_header *header; | 27 | static struct perf_header *header; |
28 | static u64 sample_type; | 28 | static u64 sample_type; |
29 | 29 | ||
30 | 30 | ||
31 | /* | ||
32 | * Scheduler benchmarks | ||
33 | */ | ||
34 | #include <sys/resource.h> | ||
35 | #include <sys/types.h> | ||
36 | #include <sys/stat.h> | ||
37 | #include <sys/time.h> | ||
38 | #include <sys/prctl.h> | ||
39 | |||
40 | #include <linux/unistd.h> | ||
41 | |||
42 | #include <semaphore.h> | ||
43 | #include <pthread.h> | ||
44 | #include <signal.h> | ||
45 | #include <values.h> | ||
46 | #include <string.h> | ||
47 | #include <unistd.h> | ||
48 | #include <stdlib.h> | ||
49 | #include <assert.h> | ||
50 | #include <fcntl.h> | ||
51 | #include <time.h> | ||
52 | #include <math.h> | ||
53 | |||
54 | #include <stdio.h> | ||
55 | |||
56 | #define PR_SET_NAME 15 /* Set process name */ | ||
57 | |||
58 | #define BUG_ON(x) assert(!(x)) | ||
59 | |||
60 | #define DEBUG 1 | ||
61 | |||
62 | typedef unsigned long long nsec_t; | ||
63 | |||
64 | #define printk(x...) do { printf(x); fflush(stdout); } while (0) | ||
65 | |||
66 | nsec_t prev_printk; | ||
67 | |||
68 | #define __dprintk(x,y...) do { \ | ||
69 | nsec_t __now = get_nsecs(), __delta = __now - prev_printk; \ | ||
70 | \ | ||
71 | prev_printk = __now; \ | ||
72 | \ | ||
73 | printf("%.3f [%Ld] [%.3f]: " x, (double)__now/1e6, __now, (double)__delta/1e6, y);\ | ||
74 | } while (0) | ||
75 | |||
76 | #if !DEBUG | ||
77 | # define dprintk(x...) do { } while (0) | ||
78 | #else | ||
79 | # define dprintk(x...) __dprintk(x) | ||
80 | #endif | ||
81 | |||
82 | #define __DP() __dprintk("parent: line %d\n", __LINE__) | ||
83 | #define DP() dprintk("parent: line %d\n", __LINE__) | ||
84 | #define D() dprintk("task %ld: line %d\n", this_task->nr, __LINE__) | ||
85 | |||
86 | |||
87 | static nsec_t run_measurement_overhead; | ||
88 | static nsec_t sleep_measurement_overhead; | ||
89 | |||
90 | static nsec_t get_nsecs(void) | ||
91 | { | ||
92 | struct timespec ts; | ||
93 | |||
94 | clock_gettime(CLOCK_MONOTONIC, &ts); | ||
95 | |||
96 | return ts.tv_sec * 1000000000ULL + ts.tv_nsec; | ||
97 | } | ||
98 | |||
99 | static void burn_nsecs(nsec_t nsecs) | ||
100 | { | ||
101 | nsec_t T0 = get_nsecs(), T1; | ||
102 | |||
103 | do { | ||
104 | T1 = get_nsecs(); | ||
105 | } while (T1 + run_measurement_overhead < T0 + nsecs); | ||
106 | } | ||
107 | |||
108 | static void sleep_nsecs(nsec_t nsecs) | ||
109 | { | ||
110 | struct timespec ts; | ||
111 | |||
112 | ts.tv_nsec = nsecs % 999999999; | ||
113 | ts.tv_sec = nsecs / 999999999; | ||
114 | |||
115 | nanosleep(&ts, NULL); | ||
116 | } | ||
117 | |||
118 | static void calibrate_run_measurement_overhead(void) | ||
119 | { | ||
120 | nsec_t T0, T1, delta, min_delta = 1000000000ULL; | ||
121 | int i; | ||
122 | |||
123 | for (i = 0; i < 10; i++) { | ||
124 | T0 = get_nsecs(); | ||
125 | burn_nsecs(0); | ||
126 | T1 = get_nsecs(); | ||
127 | delta = T1-T0; | ||
128 | min_delta = min(min_delta, delta); | ||
129 | } | ||
130 | run_measurement_overhead = min_delta; | ||
131 | |||
132 | printk("run measurement overhead: %Ld nsecs\n", min_delta); | ||
133 | } | ||
134 | |||
135 | static void calibrate_sleep_measurement_overhead(void) | ||
136 | { | ||
137 | nsec_t T0, T1, delta, min_delta = 1000000000ULL; | ||
138 | int i; | ||
139 | |||
140 | for (i = 0; i < 10; i++) { | ||
141 | T0 = get_nsecs(); | ||
142 | sleep_nsecs(10000); | ||
143 | T1 = get_nsecs(); | ||
144 | delta = T1-T0; | ||
145 | min_delta = min(min_delta, delta); | ||
146 | } | ||
147 | min_delta -= 10000; | ||
148 | sleep_measurement_overhead = min_delta; | ||
149 | |||
150 | printk("sleep measurement overhead: %Ld nsecs\n", min_delta); | ||
151 | } | ||
152 | |||
153 | #define COMM_LEN 20 | ||
154 | #define SYM_LEN 129 | ||
155 | |||
156 | #define MAX_PID 65536 | ||
157 | |||
158 | static unsigned long nr_tasks; | ||
159 | |||
160 | struct sched_event; | ||
161 | |||
162 | struct task_desc { | ||
163 | unsigned long nr; | ||
164 | unsigned long pid; | ||
165 | char comm[COMM_LEN]; | ||
166 | |||
167 | unsigned long nr_events; | ||
168 | unsigned long curr_event; | ||
169 | struct sched_event **events; | ||
170 | |||
171 | pthread_t thread; | ||
172 | sem_t sleep_sem; | ||
173 | |||
174 | sem_t ready_for_work; | ||
175 | sem_t work_done_sem; | ||
176 | |||
177 | nsec_t cpu_usage; | ||
178 | }; | ||
179 | |||
180 | enum sched_event_type { | ||
181 | SCHED_EVENT_RUN, | ||
182 | SCHED_EVENT_SLEEP, | ||
183 | SCHED_EVENT_WAKEUP, | ||
184 | }; | ||
185 | |||
186 | struct sched_event { | ||
187 | enum sched_event_type type; | ||
188 | nsec_t timestamp; | ||
189 | nsec_t duration; | ||
190 | unsigned long nr; | ||
191 | int specific_wait; | ||
192 | sem_t *wait_sem; | ||
193 | struct task_desc *wakee; | ||
194 | }; | ||
195 | |||
196 | static struct task_desc *pid_to_task[MAX_PID]; | ||
197 | |||
198 | static struct task_desc **tasks; | ||
199 | |||
200 | static pthread_mutex_t start_work_mutex = PTHREAD_MUTEX_INITIALIZER; | ||
201 | static nsec_t start_time; | ||
202 | |||
203 | static pthread_mutex_t work_done_wait_mutex = PTHREAD_MUTEX_INITIALIZER; | ||
204 | |||
205 | static unsigned long nr_run_events; | ||
206 | static unsigned long nr_sleep_events; | ||
207 | static unsigned long nr_wakeup_events; | ||
208 | |||
209 | static unsigned long nr_sleep_corrections; | ||
210 | static unsigned long nr_run_events_optimized; | ||
211 | |||
212 | static struct sched_event * | ||
213 | get_new_event(struct task_desc *task, nsec_t timestamp) | ||
214 | { | ||
215 | struct sched_event *event = calloc(1, sizeof(*event)); | ||
216 | unsigned long idx = task->nr_events; | ||
217 | size_t size; | ||
218 | |||
219 | event->timestamp = timestamp; | ||
220 | event->nr = idx; | ||
221 | |||
222 | task->nr_events++; | ||
223 | size = sizeof(struct sched_event *) * task->nr_events; | ||
224 | task->events = realloc(task->events, size); | ||
225 | BUG_ON(!task->events); | ||
226 | |||
227 | task->events[idx] = event; | ||
228 | |||
229 | return event; | ||
230 | } | ||
231 | |||
232 | static struct sched_event *last_event(struct task_desc *task) | ||
233 | { | ||
234 | if (!task->nr_events) | ||
235 | return NULL; | ||
236 | |||
237 | return task->events[task->nr_events - 1]; | ||
238 | } | ||
239 | |||
240 | static void | ||
241 | add_sched_event_run(struct task_desc *task, nsec_t timestamp, | ||
242 | unsigned long duration) | ||
243 | { | ||
244 | struct sched_event *event, *curr_event = last_event(task); | ||
245 | |||
246 | /* | ||
247 | * optimize an existing RUN event by merging this one | ||
248 | * to it: | ||
249 | */ | ||
250 | if (curr_event && curr_event->type == SCHED_EVENT_RUN) { | ||
251 | nr_run_events_optimized++; | ||
252 | curr_event->duration += duration; | ||
253 | return; | ||
254 | } | ||
255 | |||
256 | event = get_new_event(task, timestamp); | ||
257 | |||
258 | event->type = SCHED_EVENT_RUN; | ||
259 | event->duration = duration; | ||
260 | |||
261 | nr_run_events++; | ||
262 | } | ||
263 | |||
264 | static unsigned long targetless_wakeups; | ||
265 | static unsigned long multitarget_wakeups; | ||
266 | |||
267 | static void | ||
268 | add_sched_event_wakeup(struct task_desc *task, nsec_t timestamp, | ||
269 | struct task_desc *wakee) | ||
270 | { | ||
271 | struct sched_event *event, *wakee_event; | ||
272 | |||
273 | event = get_new_event(task, timestamp); | ||
274 | event->type = SCHED_EVENT_WAKEUP; | ||
275 | event->wakee = wakee; | ||
276 | |||
277 | wakee_event = last_event(wakee); | ||
278 | if (!wakee_event || wakee_event->type != SCHED_EVENT_SLEEP) { | ||
279 | targetless_wakeups++; | ||
280 | return; | ||
281 | } | ||
282 | if (wakee_event->wait_sem) { | ||
283 | multitarget_wakeups++; | ||
284 | return; | ||
285 | } | ||
286 | |||
287 | wakee_event->wait_sem = calloc(1, sizeof(*wakee_event->wait_sem)); | ||
288 | sem_init(wakee_event->wait_sem, 0, 0); | ||
289 | wakee_event->specific_wait = 1; | ||
290 | event->wait_sem = wakee_event->wait_sem; | ||
291 | |||
292 | nr_wakeup_events++; | ||
293 | } | ||
294 | |||
295 | static void | ||
296 | add_sched_event_sleep(struct task_desc *task, nsec_t timestamp, | ||
297 | unsigned long uninterruptible __used) | ||
298 | { | ||
299 | struct sched_event *event = get_new_event(task, timestamp); | ||
300 | |||
301 | event->type = SCHED_EVENT_SLEEP; | ||
302 | |||
303 | nr_sleep_events++; | ||
304 | } | ||
305 | |||
306 | static struct task_desc *register_pid(unsigned long pid, const char *comm) | ||
307 | { | ||
308 | struct task_desc *task; | ||
309 | |||
310 | BUG_ON(pid >= MAX_PID); | ||
311 | |||
312 | task = pid_to_task[pid]; | ||
313 | |||
314 | if (task) | ||
315 | return task; | ||
316 | |||
317 | task = calloc(1, sizeof(*task)); | ||
318 | task->pid = pid; | ||
319 | task->nr = nr_tasks; | ||
320 | strcpy(task->comm, comm); | ||
321 | /* | ||
322 | * every task starts in sleeping state - this gets ignored | ||
323 | * if there's no wakeup pointing to this sleep state: | ||
324 | */ | ||
325 | add_sched_event_sleep(task, 0, 0); | ||
326 | |||
327 | pid_to_task[pid] = task; | ||
328 | nr_tasks++; | ||
329 | tasks = realloc(tasks, nr_tasks*sizeof(struct task_task *)); | ||
330 | BUG_ON(!tasks); | ||
331 | tasks[task->nr] = task; | ||
332 | |||
333 | printk("registered task #%ld, PID %ld (%s)\n", nr_tasks, pid, comm); | ||
334 | |||
335 | return task; | ||
336 | } | ||
337 | |||
338 | |||
339 | static int first_trace_line = 1; | ||
340 | |||
341 | static nsec_t first_timestamp; | ||
342 | static nsec_t prev_timestamp; | ||
343 | |||
344 | void parse_line(char *line); | ||
345 | |||
346 | void parse_line(char *line) | ||
347 | { | ||
348 | unsigned long param1 = 0, param2 = 0; | ||
349 | char comm[COMM_LEN], comm2[COMM_LEN]; | ||
350 | unsigned long pid, pid2, timestamp0; | ||
351 | struct task_desc *task, *task2; | ||
352 | char func_str[SYM_LEN]; | ||
353 | nsec_t timestamp; | ||
354 | int ret; | ||
355 | |||
356 | //" <idle> 0 0D.s3 0us+: try_to_wake_up <events/0 9> (1 0)" | ||
357 | ret = sscanf(line, "%20s %5ld %*s %ldus%*c:" | ||
358 | " %128s <%20s %ld> (%ld %ld)\n", | ||
359 | comm, &pid, ×tamp0, | ||
360 | func_str, comm2, &pid2, ¶m1, ¶m2); | ||
361 | dprintk("ret: %d\n", ret); | ||
362 | if (ret != 8) | ||
363 | return; | ||
364 | |||
365 | timestamp = timestamp0 * 1000LL; | ||
366 | |||
367 | if (first_trace_line) { | ||
368 | first_trace_line = 0; | ||
369 | first_timestamp = timestamp; | ||
370 | } | ||
371 | |||
372 | timestamp -= first_timestamp; | ||
373 | BUG_ON(timestamp < prev_timestamp); | ||
374 | prev_timestamp = timestamp; | ||
375 | |||
376 | dprintk("parsed: %s - %ld %Ld: %s - <%s %ld> (%ld %ld)\n", | ||
377 | comm, | ||
378 | pid, | ||
379 | timestamp, | ||
380 | func_str, | ||
381 | comm2, | ||
382 | pid2, | ||
383 | param1, | ||
384 | param2); | ||
385 | |||
386 | task = register_pid(pid, comm); | ||
387 | task2 = register_pid(pid2, comm2); | ||
388 | |||
389 | if (!strcmp(func_str, "update_curr")) { | ||
390 | dprintk("%Ld: task %ld runs for %ld nsecs\n", | ||
391 | timestamp, task->nr, param1); | ||
392 | add_sched_event_run(task, timestamp, param1); | ||
393 | } else if (!strcmp(func_str, "try_to_wake_up")) { | ||
394 | dprintk("%Ld: task %ld wakes up task %ld\n", | ||
395 | timestamp, task->nr, task2->nr); | ||
396 | add_sched_event_wakeup(task, timestamp, task2); | ||
397 | } else if (!strcmp(func_str, "deactivate_task")) { | ||
398 | dprintk("%Ld: task %ld goes to sleep (uninterruptible: %ld)\n", | ||
399 | timestamp, task->nr, param1); | ||
400 | add_sched_event_sleep(task, timestamp, param1); | ||
401 | } | ||
402 | } | ||
403 | |||
404 | static void print_task_traces(void) | ||
405 | { | ||
406 | struct task_desc *task; | ||
407 | unsigned long i; | ||
408 | |||
409 | for (i = 0; i < nr_tasks; i++) { | ||
410 | task = tasks[i]; | ||
411 | printk("task %6ld (%20s:%10ld), nr_events: %ld\n", | ||
412 | task->nr, task->comm, task->pid, task->nr_events); | ||
413 | } | ||
414 | } | ||
415 | |||
416 | static void add_cross_task_wakeups(void) | ||
417 | { | ||
418 | struct task_desc *task1, *task2; | ||
419 | unsigned long i, j; | ||
420 | |||
421 | for (i = 0; i < nr_tasks; i++) { | ||
422 | task1 = tasks[i]; | ||
423 | j = i + 1; | ||
424 | if (j == nr_tasks) | ||
425 | j = 0; | ||
426 | task2 = tasks[j]; | ||
427 | add_sched_event_wakeup(task1, 0, task2); | ||
428 | } | ||
429 | } | ||
430 | |||
431 | static void | ||
432 | process_sched_event(struct task_desc *this_task, struct sched_event *event) | ||
433 | { | ||
434 | int ret = 0; | ||
435 | nsec_t now; | ||
436 | long long delta; | ||
437 | |||
438 | now = get_nsecs(); | ||
439 | delta = start_time + event->timestamp - now; | ||
440 | |||
441 | dprintk("task %ld, event #%ld, %Ld, delta: %.3f (%Ld)\n", | ||
442 | this_task->nr, event->nr, event->timestamp, | ||
443 | (double)delta/1e6, delta); | ||
444 | |||
445 | if (0 && delta > 0) { | ||
446 | dprintk("%.3f: task %ld FIX %.3f\n", | ||
447 | (double)event->timestamp/1e6, | ||
448 | this_task->nr, | ||
449 | (double)delta/1e6); | ||
450 | sleep_nsecs(start_time + event->timestamp - now); | ||
451 | nr_sleep_corrections++; | ||
452 | } | ||
453 | |||
454 | switch (event->type) { | ||
455 | case SCHED_EVENT_RUN: | ||
456 | dprintk("%.3f: task %ld RUN for %.3f\n", | ||
457 | (double)event->timestamp/1e6, | ||
458 | this_task->nr, | ||
459 | (double)event->duration/1e6); | ||
460 | burn_nsecs(event->duration); | ||
461 | break; | ||
462 | case SCHED_EVENT_SLEEP: | ||
463 | dprintk("%.3f: task %ld %s SLEEP\n", | ||
464 | (double)event->timestamp/1e6, | ||
465 | this_task->nr, event->wait_sem ? "" : "SKIP"); | ||
466 | if (event->wait_sem) | ||
467 | ret = sem_wait(event->wait_sem); | ||
468 | BUG_ON(ret); | ||
469 | break; | ||
470 | case SCHED_EVENT_WAKEUP: | ||
471 | dprintk("%.3f: task %ld WAKEUP => task %ld\n", | ||
472 | (double)event->timestamp/1e6, | ||
473 | this_task->nr, | ||
474 | event->wakee->nr); | ||
475 | if (event->wait_sem) | ||
476 | ret = sem_post(event->wait_sem); | ||
477 | BUG_ON(ret); | ||
478 | break; | ||
479 | default: | ||
480 | BUG_ON(1); | ||
481 | } | ||
482 | } | ||
483 | |||
484 | static nsec_t get_cpu_usage_nsec_parent(void) | ||
485 | { | ||
486 | struct rusage ru; | ||
487 | nsec_t sum; | ||
488 | int err; | ||
489 | |||
490 | err = getrusage(RUSAGE_SELF, &ru); | ||
491 | BUG_ON(err); | ||
492 | |||
493 | sum = ru.ru_utime.tv_sec*1e9 + ru.ru_utime.tv_usec*1e3; | ||
494 | sum += ru.ru_stime.tv_sec*1e9 + ru.ru_stime.tv_usec*1e3; | ||
495 | |||
496 | return sum; | ||
497 | } | ||
498 | |||
499 | static nsec_t get_cpu_usage_nsec_self(void) | ||
500 | { | ||
501 | char filename [] = "/proc/1234567890/sched"; | ||
502 | unsigned long msecs, nsecs; | ||
503 | char *line = NULL; | ||
504 | nsec_t total = 0; | ||
505 | size_t len = 0; | ||
506 | ssize_t chars; | ||
507 | FILE *file; | ||
508 | int ret; | ||
509 | |||
510 | sprintf(filename, "/proc/%d/sched", getpid()); | ||
511 | file = fopen(filename, "r"); | ||
512 | BUG_ON(!file); | ||
513 | |||
514 | while ((chars = getline(&line, &len, file)) != -1) { | ||
515 | dprintk("got line with length %zu :\n", chars); | ||
516 | dprintk("%s", line); | ||
517 | ret = sscanf(line, "se.sum_exec_runtime : %ld.%06ld\n", | ||
518 | &msecs, &nsecs); | ||
519 | if (ret == 2) { | ||
520 | total = msecs*1e6 + nsecs; | ||
521 | dprintk("total: (%ld.%06ld) %Ld\n", | ||
522 | msecs, nsecs, total); | ||
523 | break; | ||
524 | } | ||
525 | } | ||
526 | if (line) | ||
527 | free(line); | ||
528 | fclose(file); | ||
529 | |||
530 | return total; | ||
531 | } | ||
532 | |||
533 | static void *thread_func(void *ctx) | ||
534 | { | ||
535 | struct task_desc *this_task = ctx; | ||
536 | nsec_t cpu_usage_0, cpu_usage_1; | ||
537 | unsigned long i, ret; | ||
538 | char comm2[22]; | ||
539 | |||
540 | dprintk("task %ld started up.\n", this_task->nr); | ||
541 | sprintf(comm2, ":%s", this_task->comm); | ||
542 | prctl(PR_SET_NAME, comm2); | ||
543 | |||
544 | again: | ||
545 | ret = sem_post(&this_task->ready_for_work); | ||
546 | BUG_ON(ret); | ||
547 | D(); | ||
548 | ret = pthread_mutex_lock(&start_work_mutex); | ||
549 | BUG_ON(ret); | ||
550 | ret = pthread_mutex_unlock(&start_work_mutex); | ||
551 | BUG_ON(ret); | ||
552 | D(); | ||
553 | |||
554 | cpu_usage_0 = get_cpu_usage_nsec_self(); | ||
555 | |||
556 | for (i = 0; i < this_task->nr_events; i++) { | ||
557 | this_task->curr_event = i; | ||
558 | process_sched_event(this_task, this_task->events[i]); | ||
559 | } | ||
560 | |||
561 | cpu_usage_1 = get_cpu_usage_nsec_self(); | ||
562 | this_task->cpu_usage = cpu_usage_1 - cpu_usage_0; | ||
563 | |||
564 | dprintk("task %ld cpu usage: %0.3f msecs\n", | ||
565 | this_task->nr, (double)this_task->cpu_usage / 1e6); | ||
566 | |||
567 | D(); | ||
568 | ret = sem_post(&this_task->work_done_sem); | ||
569 | BUG_ON(ret); | ||
570 | D(); | ||
571 | |||
572 | ret = pthread_mutex_lock(&work_done_wait_mutex); | ||
573 | BUG_ON(ret); | ||
574 | ret = pthread_mutex_unlock(&work_done_wait_mutex); | ||
575 | BUG_ON(ret); | ||
576 | D(); | ||
577 | |||
578 | goto again; | ||
579 | } | ||
580 | |||
581 | static void create_tasks(void) | ||
582 | { | ||
583 | struct task_desc *task; | ||
584 | pthread_attr_t attr; | ||
585 | unsigned long i; | ||
586 | int err; | ||
587 | |||
588 | err = pthread_attr_init(&attr); | ||
589 | BUG_ON(err); | ||
590 | err = pthread_attr_setstacksize(&attr, (size_t)(16*1024)); | ||
591 | BUG_ON(err); | ||
592 | err = pthread_mutex_lock(&start_work_mutex); | ||
593 | BUG_ON(err); | ||
594 | err = pthread_mutex_lock(&work_done_wait_mutex); | ||
595 | BUG_ON(err); | ||
596 | for (i = 0; i < nr_tasks; i++) { | ||
597 | task = tasks[i]; | ||
598 | sem_init(&task->sleep_sem, 0, 0); | ||
599 | sem_init(&task->ready_for_work, 0, 0); | ||
600 | sem_init(&task->work_done_sem, 0, 0); | ||
601 | task->curr_event = 0; | ||
602 | err = pthread_create(&task->thread, &attr, thread_func, task); | ||
603 | BUG_ON(err); | ||
604 | } | ||
605 | } | ||
606 | |||
607 | static nsec_t cpu_usage; | ||
608 | static nsec_t runavg_cpu_usage; | ||
609 | static nsec_t parent_cpu_usage; | ||
610 | static nsec_t runavg_parent_cpu_usage; | ||
611 | |||
612 | static void wait_for_tasks(void) | ||
613 | { | ||
614 | nsec_t cpu_usage_0, cpu_usage_1; | ||
615 | struct task_desc *task; | ||
616 | unsigned long i, ret; | ||
617 | |||
618 | DP(); | ||
619 | start_time = get_nsecs(); | ||
620 | DP(); | ||
621 | cpu_usage = 0; | ||
622 | pthread_mutex_unlock(&work_done_wait_mutex); | ||
623 | |||
624 | for (i = 0; i < nr_tasks; i++) { | ||
625 | task = tasks[i]; | ||
626 | ret = sem_wait(&task->ready_for_work); | ||
627 | BUG_ON(ret); | ||
628 | sem_init(&task->ready_for_work, 0, 0); | ||
629 | } | ||
630 | ret = pthread_mutex_lock(&work_done_wait_mutex); | ||
631 | BUG_ON(ret); | ||
632 | |||
633 | cpu_usage_0 = get_cpu_usage_nsec_parent(); | ||
634 | |||
635 | pthread_mutex_unlock(&start_work_mutex); | ||
636 | |||
637 | #if 0 | ||
638 | for (i = 0; i < nr_tasks; i++) { | ||
639 | unsigned long missed; | ||
640 | |||
641 | task = tasks[i]; | ||
642 | while (task->curr_event + 1 < task->nr_events) { | ||
643 | dprintk("parent waiting for %ld (%ld != %ld)\n", | ||
644 | i, task->curr_event, task->nr_events); | ||
645 | sleep_nsecs(100000000); | ||
646 | } | ||
647 | missed = task->nr_events - 1 - task->curr_event; | ||
648 | if (missed) | ||
649 | printk("task %ld missed events: %ld\n", i, missed); | ||
650 | ret = sem_post(&task->sleep_sem); | ||
651 | BUG_ON(ret); | ||
652 | } | ||
653 | #endif | ||
654 | DP(); | ||
655 | for (i = 0; i < nr_tasks; i++) { | ||
656 | task = tasks[i]; | ||
657 | ret = sem_wait(&task->work_done_sem); | ||
658 | BUG_ON(ret); | ||
659 | sem_init(&task->work_done_sem, 0, 0); | ||
660 | cpu_usage += task->cpu_usage; | ||
661 | task->cpu_usage = 0; | ||
662 | } | ||
663 | |||
664 | cpu_usage_1 = get_cpu_usage_nsec_parent(); | ||
665 | if (!runavg_cpu_usage) | ||
666 | runavg_cpu_usage = cpu_usage; | ||
667 | runavg_cpu_usage = (runavg_cpu_usage*9 + cpu_usage)/10; | ||
668 | |||
669 | parent_cpu_usage = cpu_usage_1 - cpu_usage_0; | ||
670 | if (!runavg_parent_cpu_usage) | ||
671 | runavg_parent_cpu_usage = parent_cpu_usage; | ||
672 | runavg_parent_cpu_usage = (runavg_parent_cpu_usage*9 + | ||
673 | parent_cpu_usage)/10; | ||
674 | |||
675 | ret = pthread_mutex_lock(&start_work_mutex); | ||
676 | BUG_ON(ret); | ||
677 | |||
678 | for (i = 0; i < nr_tasks; i++) { | ||
679 | task = tasks[i]; | ||
680 | sem_init(&task->sleep_sem, 0, 0); | ||
681 | task->curr_event = 0; | ||
682 | } | ||
683 | } | ||
684 | |||
685 | static int __cmd_sched(void); | ||
686 | |||
687 | static void parse_trace(void) | ||
688 | { | ||
689 | __cmd_sched(); | ||
690 | |||
691 | printk("nr_run_events: %ld\n", nr_run_events); | ||
692 | printk("nr_sleep_events: %ld\n", nr_sleep_events); | ||
693 | printk("nr_wakeup_events: %ld\n", nr_wakeup_events); | ||
694 | |||
695 | if (targetless_wakeups) | ||
696 | printk("target-less wakeups: %ld\n", targetless_wakeups); | ||
697 | if (multitarget_wakeups) | ||
698 | printk("multi-target wakeups: %ld\n", multitarget_wakeups); | ||
699 | if (nr_run_events_optimized) | ||
700 | printk("run events optimized: %ld\n", | ||
701 | nr_run_events_optimized); | ||
702 | } | ||
703 | |||
704 | static unsigned long nr_runs; | ||
705 | static nsec_t sum_runtime; | ||
706 | static nsec_t sum_fluct; | ||
707 | static nsec_t run_avg; | ||
708 | |||
709 | static void run_one_test(void) | ||
710 | { | ||
711 | nsec_t T0, T1, delta, avg_delta, fluct, std_dev; | ||
712 | |||
713 | T0 = get_nsecs(); | ||
714 | wait_for_tasks(); | ||
715 | T1 = get_nsecs(); | ||
716 | |||
717 | delta = T1 - T0; | ||
718 | sum_runtime += delta; | ||
719 | nr_runs++; | ||
720 | |||
721 | avg_delta = sum_runtime / nr_runs; | ||
722 | if (delta < avg_delta) | ||
723 | fluct = avg_delta - delta; | ||
724 | else | ||
725 | fluct = delta - avg_delta; | ||
726 | sum_fluct += fluct; | ||
727 | std_dev = sum_fluct / nr_runs / sqrt(nr_runs); | ||
728 | if (!run_avg) | ||
729 | run_avg = delta; | ||
730 | run_avg = (run_avg*9 + delta)/10; | ||
731 | |||
732 | printk("#%-3ld: %0.3f, ", | ||
733 | nr_runs, (double)delta/1000000.0); | ||
734 | |||
735 | #if 0 | ||
736 | printk("%0.2f +- %0.2f, ", | ||
737 | (double)avg_delta/1e6, (double)std_dev/1e6); | ||
738 | #endif | ||
739 | printk("ravg: %0.2f, ", | ||
740 | (double)run_avg/1e6); | ||
741 | |||
742 | printk("cpu: %0.2f / %0.2f", | ||
743 | (double)cpu_usage/1e6, (double)runavg_cpu_usage/1e6); | ||
744 | |||
745 | #if 0 | ||
746 | /* | ||
747 | * rusage statistics done by the parent, these are less | ||
748 | * accurate than the sum_exec_runtime based statistics: | ||
749 | */ | ||
750 | printk(" [%0.2f / %0.2f]", | ||
751 | (double)parent_cpu_usage/1e6, | ||
752 | (double)runavg_parent_cpu_usage/1e6); | ||
753 | #endif | ||
754 | |||
755 | printk("\n"); | ||
756 | |||
757 | if (nr_sleep_corrections) | ||
758 | printk(" (%ld sleep corrections)\n", nr_sleep_corrections); | ||
759 | nr_sleep_corrections = 0; | ||
760 | } | ||
761 | |||
762 | static void test_calibrations(void) | ||
763 | { | ||
764 | nsec_t T0, T1; | ||
765 | |||
766 | T0 = get_nsecs(); | ||
767 | burn_nsecs(1e6); | ||
768 | T1 = get_nsecs(); | ||
769 | |||
770 | printk("the run test took %Ld nsecs\n", T1-T0); | ||
771 | |||
772 | T0 = get_nsecs(); | ||
773 | sleep_nsecs(1e6); | ||
774 | T1 = get_nsecs(); | ||
775 | |||
776 | printk("the sleep test took %Ld nsecs\n", T1-T0); | ||
777 | } | ||
778 | |||
31 | static int | 779 | static int |
32 | process_comm_event(event_t *event, unsigned long offset, unsigned long head) | 780 | process_comm_event(event_t *event, unsigned long offset, unsigned long head) |
33 | { | 781 | { |
@@ -50,6 +798,46 @@ process_comm_event(event_t *event, unsigned long offset, unsigned long head) | |||
50 | return 0; | 798 | return 0; |
51 | } | 799 | } |
52 | 800 | ||
801 | static void process_sched_wakeup_event(struct event *event, | ||
802 | int cpu __used, u64 timestamp __used, struct thread *thread __used) | ||
803 | { | ||
804 | printf("sched_wakeup event %p\n", event); | ||
805 | } | ||
806 | |||
807 | static void process_sched_switch_event(struct event *event, | ||
808 | int cpu __used, u64 timestamp __used, struct thread *thread __used) | ||
809 | { | ||
810 | printf("sched_switch event %p\n", event); | ||
811 | } | ||
812 | |||
813 | static void | ||
814 | process_raw_event(event_t *raw_event, void *more_data, | ||
815 | int cpu, u64 timestamp, struct thread *thread) | ||
816 | { | ||
817 | struct { | ||
818 | u32 size; | ||
819 | char data[0]; | ||
820 | } *raw = more_data; | ||
821 | struct event *event; | ||
822 | int type; | ||
823 | |||
824 | type = trace_parse_common_type(raw->data); | ||
825 | event = trace_find_event(type); | ||
826 | |||
827 | /* | ||
828 | * FIXME: better resolve from pid from the struct trace_entry | ||
829 | * field, although it should be the same than this perf | ||
830 | * event pid | ||
831 | */ | ||
832 | printf("id %d, type: %d, event: %s\n", | ||
833 | raw_event->header.type, type, event->name); | ||
834 | |||
835 | if (!strcmp(event->name, "sched_switch")) | ||
836 | process_sched_switch_event(event, cpu, timestamp, thread); | ||
837 | if (!strcmp(event->name, "sched_wakeup")) | ||
838 | process_sched_wakeup_event(event, cpu, timestamp, thread); | ||
839 | } | ||
840 | |||
53 | static int | 841 | static int |
54 | process_sample_event(event_t *event, unsigned long offset, unsigned long head) | 842 | process_sample_event(event_t *event, unsigned long offset, unsigned long head) |
55 | { | 843 | { |
@@ -122,20 +910,8 @@ process_sample_event(event_t *event, unsigned long offset, unsigned long head) | |||
122 | dump_printf(" ...... dso: [hypervisor]\n"); | 910 | dump_printf(" ...... dso: [hypervisor]\n"); |
123 | } | 911 | } |
124 | 912 | ||
125 | if (sample_type & PERF_SAMPLE_RAW) { | 913 | if (sample_type & PERF_SAMPLE_RAW) |
126 | struct { | 914 | process_raw_event(event, more_data, cpu, timestamp, thread); |
127 | u32 size; | ||
128 | char data[0]; | ||
129 | } *raw = more_data; | ||
130 | |||
131 | /* | ||
132 | * FIXME: better resolve from pid from the struct trace_entry | ||
133 | * field, although it should be the same than this perf | ||
134 | * event pid | ||
135 | */ | ||
136 | print_event(cpu, raw->data, raw->size, timestamp, thread->comm); | ||
137 | } | ||
138 | total += period; | ||
139 | 915 | ||
140 | return 0; | 916 | return 0; |
141 | } | 917 | } |
@@ -277,6 +1053,8 @@ static const struct option options[] = { | |||
277 | 1053 | ||
278 | int cmd_sched(int argc, const char **argv, const char *prefix __used) | 1054 | int cmd_sched(int argc, const char **argv, const char *prefix __used) |
279 | { | 1055 | { |
1056 | long nr_iterations = LONG_MAX, i; | ||
1057 | |||
280 | symbol__init(); | 1058 | symbol__init(); |
281 | page_size = getpagesize(); | 1059 | page_size = getpagesize(); |
282 | 1060 | ||
@@ -293,5 +1071,19 @@ int cmd_sched(int argc, const char **argv, const char *prefix __used) | |||
293 | 1071 | ||
294 | setup_pager(); | 1072 | setup_pager(); |
295 | 1073 | ||
296 | return __cmd_sched(); | 1074 | calibrate_run_measurement_overhead(); |
1075 | calibrate_sleep_measurement_overhead(); | ||
1076 | |||
1077 | test_calibrations(); | ||
1078 | |||
1079 | parse_trace(); | ||
1080 | print_task_traces(); | ||
1081 | add_cross_task_wakeups(); | ||
1082 | |||
1083 | create_tasks(); | ||
1084 | printk("------------------------------------------------------------\n"); | ||
1085 | for (i = 0; i < nr_iterations; i++) | ||
1086 | run_one_test(); | ||
1087 | |||
1088 | return 0; | ||
297 | } | 1089 | } |
diff --git a/tools/perf/util/trace-event-parse.c b/tools/perf/util/trace-event-parse.c index 629e602d9405..16cf2d51c4e1 100644 --- a/tools/perf/util/trace-event-parse.c +++ b/tools/perf/util/trace-event-parse.c | |||
@@ -1799,7 +1799,7 @@ static int get_common_info(const char *type, int *offset, int *size) | |||
1799 | return 0; | 1799 | return 0; |
1800 | } | 1800 | } |
1801 | 1801 | ||
1802 | static int parse_common_type(void *data) | 1802 | int trace_parse_common_type(void *data) |
1803 | { | 1803 | { |
1804 | static int type_offset; | 1804 | static int type_offset; |
1805 | static int type_size; | 1805 | static int type_size; |
@@ -1832,7 +1832,7 @@ static int parse_common_pid(void *data) | |||
1832 | return read_size(data + pid_offset, pid_size); | 1832 | return read_size(data + pid_offset, pid_size); |
1833 | } | 1833 | } |
1834 | 1834 | ||
1835 | static struct event *find_event(int id) | 1835 | struct event *trace_find_event(int id) |
1836 | { | 1836 | { |
1837 | struct event *event; | 1837 | struct event *event; |
1838 | 1838 | ||
@@ -2420,8 +2420,8 @@ get_return_for_leaf(int cpu, int cur_pid, unsigned long long cur_func, | |||
2420 | int type; | 2420 | int type; |
2421 | int pid; | 2421 | int pid; |
2422 | 2422 | ||
2423 | type = parse_common_type(next->data); | 2423 | type = trace_parse_common_type(next->data); |
2424 | event = find_event(type); | 2424 | event = trace_find_event(type); |
2425 | if (!event) | 2425 | if (!event) |
2426 | return NULL; | 2426 | return NULL; |
2427 | 2427 | ||
@@ -2502,8 +2502,8 @@ print_graph_entry_leaf(struct event *event, void *data, struct record *ret_rec) | |||
2502 | int type; | 2502 | int type; |
2503 | int i; | 2503 | int i; |
2504 | 2504 | ||
2505 | type = parse_common_type(ret_rec->data); | 2505 | type = trace_parse_common_type(ret_rec->data); |
2506 | ret_event = find_event(type); | 2506 | ret_event = trace_find_event(type); |
2507 | 2507 | ||
2508 | field = find_field(ret_event, "rettime"); | 2508 | field = find_field(ret_event, "rettime"); |
2509 | if (!field) | 2509 | if (!field) |
@@ -2696,9 +2696,9 @@ void print_event(int cpu, void *data, int size, unsigned long long nsecs, | |||
2696 | nsecs -= secs * NSECS_PER_SEC; | 2696 | nsecs -= secs * NSECS_PER_SEC; |
2697 | usecs = nsecs / NSECS_PER_USEC; | 2697 | usecs = nsecs / NSECS_PER_USEC; |
2698 | 2698 | ||
2699 | type = parse_common_type(data); | 2699 | type = trace_parse_common_type(data); |
2700 | 2700 | ||
2701 | event = find_event(type); | 2701 | event = trace_find_event(type); |
2702 | if (!event) | 2702 | if (!event) |
2703 | die("ug! no event found for type %d", type); | 2703 | die("ug! no event found for type %d", type); |
2704 | 2704 | ||
diff --git a/tools/perf/util/trace-event.h b/tools/perf/util/trace-event.h index 420294a5773e..bc81612fd244 100644 --- a/tools/perf/util/trace-event.h +++ b/tools/perf/util/trace-event.h | |||
@@ -234,6 +234,8 @@ extern int header_page_data_offset; | |||
234 | extern int header_page_data_size; | 234 | extern int header_page_data_size; |
235 | 235 | ||
236 | int parse_header_page(char *buf, unsigned long size); | 236 | int parse_header_page(char *buf, unsigned long size); |
237 | int trace_parse_common_type(void *data); | ||
238 | struct event *trace_find_event(int id); | ||
237 | 239 | ||
238 | void read_tracing_data(struct perf_counter_attr *pattrs, int nb_counters); | 240 | void read_tracing_data(struct perf_counter_attr *pattrs, int nb_counters); |
239 | 241 | ||