diff --git a/kernel/futex.c b/kernel/futex.c index b9999093..373e59b3 100644 --- a/kernel/futex.c +++ b/kernel/futex.c @@ -788,6 +788,15 @@ static int futex_wait(uint32_t __user *uaddr, int fshared, if (!bitset) return -EINVAL; +#ifdef PROFILE_ENABLE + if (cpu_local_var(current)->profile && + cpu_local_var(current)->profile_start_ts) { + cpu_local_var(current)->profile_elapsed_ts += + (rdtsc() - cpu_local_var(current)->profile_start_ts); + cpu_local_var(current)->profile_start_ts = 0; + } +#endif + q.bitset = bitset; q.requeue_pi_key = NULL; @@ -822,6 +831,11 @@ retry: out_put_key: put_futex_key(fshared, &q.key); out: +#ifdef PROFILE_ENABLE + if (cpu_local_var(current)->profile) { + cpu_local_var(current)->profile_start_ts = rdtsc(); + } +#endif return ret; } diff --git a/kernel/include/process.h b/kernel/include/process.h index 67773fc4..79efc9b7 100644 --- a/kernel/include/process.h +++ b/kernel/include/process.h @@ -554,6 +554,7 @@ struct process { int profile; mcs_lock_node_t profile_lock; struct profile_event *profile_events; + unsigned long profile_elapsed_ts; #endif // PROFILE_ENABLE int nr_processes; /* For partitioned execution */ }; @@ -631,6 +632,8 @@ struct thread { #ifdef PROFILE_ENABLE int profile; struct profile_event *profile_events; + unsigned long profile_start_ts; + unsigned long profile_elapsed_ts; #endif // PROFILE_ENABLE // signal diff --git a/kernel/process.c b/kernel/process.c index 11cfbb14..537f7787 100644 --- a/kernel/process.c +++ b/kernel/process.c @@ -2966,6 +2966,19 @@ redo: perf_start(next->proc->monitoring_event); } } + +#ifdef PROFILE_ENABLE + if (prev->profile && prev->profile_start_ts != 0) { + prev->profile_elapsed_ts += + (rdtsc() - prev->profile_start_ts); + prev->profile_start_ts = 0; + } + + if (next->profile && next->profile_start_ts == 0) { + next->profile_start_ts = rdtsc(); + } +#endif + if (prev) { last = ihk_mc_switch_context(&prev->ctx, &next->ctx, prev); } diff --git a/kernel/profile.c b/kernel/profile.c index aba2f985..14cb9f01 100644 --- a/kernel/profile.c +++ b/kernel/profile.c @@ -74,6 +74,7 @@ mcs_lock_node_t job_profile_lock = {0, NULL}; struct profile_event *job_profile_events = NULL; int job_nr_processes = -1; int job_nr_processes_left = -1; +unsigned long job_elapsed_ts; @@ -111,16 +112,26 @@ void profile_print_thread_stats(struct thread *thread) int i; unsigned long flags; - if (!thread->profile_events) return; + if (!thread->profile_events) + return; + + /* Not yet accumulated period? */ + if (thread->profile_start_ts) { + thread->profile_elapsed_ts += (rdtsc() - thread->profile_start_ts); + } flags = kprintf_lock(); + __kprintf("TID: %4d elapsed cycles (excluding idle): %luk\n", + thread->tid, + thread->profile_elapsed_ts / 1000); + for (i = 0; i < PROFILE_SYSCALL_MAX; ++i) { if (!thread->profile_events[i].cnt && - !thread->profile_events[i + PROFILE_SYSCALL_MAX].cnt) + !thread->profile_events[i + PROFILE_SYSCALL_MAX].cnt) continue; - __kprintf("TID: %4d (%3d,%20s): %6u %6luk offl: %6u %6luk\n", + __kprintf("TID: %4d (%3d,%20s): %6u %6luk offl: %6u %6luk (%2d.%2d%%)\n", thread->tid, i, syscall_name[i], @@ -133,7 +144,13 @@ void profile_print_thread_stats(struct thread *thread) (thread->profile_events[i + PROFILE_SYSCALL_MAX].tsc / (thread->profile_events[i + PROFILE_SYSCALL_MAX].cnt ? thread->profile_events[i + PROFILE_SYSCALL_MAX].cnt : 1)) - / 1000 + / 1000, + (thread->profile_events[i].tsc ? + thread->profile_events[i].tsc * 100 + / thread->profile_elapsed_ts : 0), + (thread->profile_events[i].tsc ? + (thread->profile_events[i].tsc * 10000 + / thread->profile_elapsed_ts) % 100 : 0) ); } @@ -149,7 +166,14 @@ void profile_print_thread_stats(struct thread *thread) (thread->profile_events[i].tsc / (thread->profile_events[i].cnt ? thread->profile_events[i].cnt : 1)) - / 1000); + / 1000, + (thread->profile_events[i].tsc ? + thread->profile_events[i].tsc * 100 + / thread->profile_elapsed_ts : 0), + (thread->profile_events[i].tsc ? + (thread->profile_events[i].tsc * 10000 + / thread->profile_elapsed_ts) % 100 : 0) + ); } @@ -161,16 +185,20 @@ void profile_print_proc_stats(struct process *proc) int i; unsigned long flags; - if (!proc->profile_events) return; + if (!proc->profile_events || !proc->profile_elapsed_ts) + return; flags = kprintf_lock(); + __kprintf("PID: %4d elapsed cycles for all threads (excluding idle): %luk\n", + proc->pid, + proc->profile_elapsed_ts / 1000); for (i = 0; i < PROFILE_SYSCALL_MAX; ++i) { if (!proc->profile_events[i].cnt && - !proc->profile_events[i + PROFILE_SYSCALL_MAX].cnt) + !proc->profile_events[i + PROFILE_SYSCALL_MAX].cnt) continue; - __kprintf("PID: %4d (%3d,%20s): %6u %6luk offl: %6u %6luk\n", + __kprintf("PID: %4d (%3d,%20s): %6u %6luk offl: %6u %6luk (%2d.%2d%%)\n", proc->pid, i, syscall_name[i], @@ -183,7 +211,13 @@ void profile_print_proc_stats(struct process *proc) (proc->profile_events[i + PROFILE_SYSCALL_MAX].tsc / (proc->profile_events[i + PROFILE_SYSCALL_MAX].cnt ? proc->profile_events[i + PROFILE_SYSCALL_MAX].cnt : 1)) - / 1000 + / 1000, + (proc->profile_events[i].tsc ? + proc->profile_events[i].tsc * 100 + / proc->profile_elapsed_ts : 0), + (proc->profile_events[i].tsc ? + (proc->profile_events[i].tsc * 10000 + / proc->profile_elapsed_ts) % 100 : 0) ); } @@ -199,7 +233,16 @@ void profile_print_proc_stats(struct process *proc) (proc->profile_events[i].tsc / (proc->profile_events[i].cnt ? proc->profile_events[i].cnt : 1)) - / 1000); + / 1000, + (proc->profile_events[i].tsc && + proc->profile_elapsed_ts ? + proc->profile_events[i].tsc * 100 + / proc->profile_elapsed_ts : 0), + (proc->profile_events[i].tsc && + proc->profile_elapsed_ts ? + (proc->profile_events[i].tsc * 10000 + / proc->profile_elapsed_ts) % 100 : 0) + ); } kprintf_unlock(flags); @@ -217,6 +260,7 @@ int profile_accumulate_and_print_job_events(struct process *proc) if (job_nr_processes == -1) { job_nr_processes = proc->nr_processes; job_nr_processes_left = proc->nr_processes; + job_elapsed_ts = 0; } --job_nr_processes_left; @@ -248,16 +292,21 @@ int profile_accumulate_and_print_job_events(struct process *proc) proc->profile_events[i].cnt = 0; } + job_elapsed_ts += proc->profile_elapsed_ts; + /* Last process? */ if (job_nr_processes_left == 0) { flags = kprintf_lock(); + __kprintf("JOB: (%2d) elapsed cycles for all threads (excluding idle): %luk\n", + job_nr_processes, + job_elapsed_ts / 1000); for (i = 0; i < PROFILE_SYSCALL_MAX; ++i) { if (!job_profile_events[i].cnt && !job_profile_events[i + PROFILE_SYSCALL_MAX].cnt) continue; - __kprintf("JOB: (%2d) (%3d,%20s): %6u %6luk offl: %6u %6luk\n", + __kprintf("JOB: (%2d) (%3d,%20s): %6u %6luk offl: %6u %6luk (%2d.%2d%%)\n", job_nr_processes, i, syscall_name[i], @@ -270,7 +319,13 @@ int profile_accumulate_and_print_job_events(struct process *proc) (job_profile_events[i + PROFILE_SYSCALL_MAX].tsc / (job_profile_events[i + PROFILE_SYSCALL_MAX].cnt ? job_profile_events[i + PROFILE_SYSCALL_MAX].cnt : 1)) - / 1000 + / 1000, + (job_profile_events[i].tsc ? + job_profile_events[i].tsc * 100 + / job_elapsed_ts : 0), + (job_profile_events[i].tsc ? + (job_profile_events[i].tsc * 10000 + / job_elapsed_ts) % 100 : 0) ); job_profile_events[i].tsc = 0; @@ -302,6 +357,7 @@ int profile_accumulate_and_print_job_events(struct process *proc) /* Reset job process indicators */ job_nr_processes = -1; job_nr_processes_left = -1; + job_elapsed_ts = 0; } mcs_lock_unlock(&job_profile_lock, &mcs_node); @@ -326,6 +382,12 @@ void profile_accumulate_events(struct thread *thread, thread->profile_events[i].cnt = 0; } + proc->profile_elapsed_ts += thread->profile_elapsed_ts; + if (thread->profile_start_ts) { + proc->profile_elapsed_ts += + (rdtsc() - thread->profile_start_ts); + } + mcs_lock_unlock(&proc->profile_lock, &mcs_node); } @@ -381,6 +443,7 @@ void profile_dealloc_proc_events(struct process *proc) void static profile_clear_process(struct process *proc) { + proc->profile_elapsed_ts = 0; if (!proc->profile_events) return; memset(proc->profile_events, 0, @@ -389,6 +452,8 @@ void static profile_clear_process(struct process *proc) void static profile_clear_thread(struct thread *thread) { + thread->profile_start_ts = 0; + thread->profile_elapsed_ts = 0; if (!thread->profile_events) return; memset(thread->profile_events, 0, @@ -399,6 +464,7 @@ int do_profile(int flag) { struct thread *thread = cpu_local_var(current); struct process *proc = thread->proc; + unsigned long now_ts = rdtsc(); /* Job level? */ if (flag & PROF_JOB) { @@ -444,7 +510,14 @@ int do_profile(int flag) _thread->profile = 1; } else if (flag & PROF_OFF) { - _thread->profile = 0; + if (_thread->profile) { + _thread->profile = 0; + if (_thread->profile_start_ts) { + _thread->profile_elapsed_ts += + (now_ts - _thread->profile_start_ts); + } + _thread->profile_start_ts = 0; + } } } @@ -460,7 +533,9 @@ int do_profile(int flag) /* Make sure future threads profile as well */ if (flag & PROF_ON) { - proc->profile = 1; + if (!proc->profile) { + proc->profile = 1; + } } else if (flag & PROF_OFF) { proc->profile = 0; @@ -476,13 +551,28 @@ int do_profile(int flag) if (flag & PROF_CLEAR) { profile_clear_thread(thread); + /* If profiling, reset start and elapsed */ + if (thread->profile) { + thread->profile_start_ts = 0; + thread->profile_elapsed_ts = 0; + } } if (flag & PROF_ON) { - thread->profile = 1; + if (!thread->profile) { + thread->profile = 1; + thread->profile_start_ts = 0; + } } else if (flag & PROF_OFF) { - thread->profile = 0; + if (thread->profile) { + thread->profile = 0; + if (thread->profile_start_ts) { + thread->profile_elapsed_ts += + (now_ts - thread->profile_start_ts); + } + thread->profile_start_ts = 0; + } } } diff --git a/kernel/syscall.c b/kernel/syscall.c index c6cb8359..0bc6f224 100644 --- a/kernel/syscall.c +++ b/kernel/syscall.c @@ -9307,9 +9307,6 @@ set_cputime(int mode) long syscall(int num, ihk_mc_user_context_t *ctx) { long l; -#ifdef PROFILE_ENABLE - uint64_t t_s; -#endif // PROFILE_ENABLE struct thread *thread = cpu_local_var(current); #ifdef DISABLE_SCHED_YIELD @@ -9317,6 +9314,14 @@ long syscall(int num, ihk_mc_user_context_t *ctx) #endif // DISABLE_SCHED_YIELD set_cputime(1); +#ifdef PROFILE_ENABLE + if (thread->profile && thread->profile_start_ts) { + unsigned long ts = rdtsc(); + thread->profile_elapsed_ts += (ts - thread->profile_start_ts); + thread->profile_start_ts = ts; + } +#endif // PROFILE_ENABLE + if(cpu_local_var(current)->proc->status == PS_EXITED && (num != __NR_exit && num != __NR_exit_group)){ check_signal(-EINVAL, NULL, 0); @@ -9356,10 +9361,6 @@ long syscall(int num, ihk_mc_user_context_t *ctx) #endif dkprintf("\n"); -#ifdef PROFILE_ENABLE - t_s = rdtsc(); -#endif // PROFILE_ENABLE - if ((0 <= num) && (num < (sizeof(syscall_table) / sizeof(syscall_table[0]))) && (syscall_table[num] != NULL)) { l = syscall_table[num](num, ctx); @@ -9381,13 +9382,22 @@ long syscall(int num, ihk_mc_user_context_t *ctx) } #ifdef PROFILE_ENABLE - if (num < PROFILE_SYSCALL_MAX) { - profile_event_add(num, (rdtsc() - t_s)); - } - else { - if (num != __NR_profile) { - dkprintf("%s: syscall > %d ?? : %d\n", - __FUNCTION__, PROFILE_SYSCALL_MAX, num); + if (thread->profile) { + unsigned long ts = rdtsc(); + + /* + * futex_wait() and schedule() will internally reset + * thread->profile_start_ts so that actual wait time + * is not accounted for. + */ + if (num < PROFILE_SYSCALL_MAX) { + profile_event_add(num, (ts - thread->profile_start_ts)); + } + else { + if (num != __NR_profile) { + dkprintf("%s: syscall > %d ?? : %d\n", + __FUNCTION__, PROFILE_SYSCALL_MAX, num); + } } } #endif // PROFILE_ENABLE