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 | ||
