diff --git a/src/libos/src/process/task/exec.rs b/src/libos/src/process/task/exec.rs index 617dd755..178ca48e 100644 --- a/src/libos/src/process/task/exec.rs +++ b/src/libos/src/process/task/exec.rs @@ -39,25 +39,11 @@ pub fn exec(libos_tid: pid_t, host_tid: pid_t) -> Result { // Enable current::get() from now on current::set(this_thread.clone()); - #[cfg(feature = "syscall_timing")] - GLOBAL_PROFILER - .lock() - .unwrap() - .thread_enter() - .expect("unexpected error from profiler to enter thread"); - unsafe { // task may only be modified by this function; so no lock is needed do_exec_task(this_thread.task() as *const Task as *mut Task); } - #[cfg(feature = "syscall_timing")] - GLOBAL_PROFILER - .lock() - .unwrap() - .thread_exit() - .expect("unexpected error from profiler to exit thread"); - let term_status = this_thread.inner().term_status().unwrap(); match term_status { TermStatus::Exited(status) => { diff --git a/src/libos/src/process/thread/builder.rs b/src/libos/src/process/thread/builder.rs index 3d088349..52ff3934 100644 --- a/src/libos/src/process/thread/builder.rs +++ b/src/libos/src/process/thread/builder.rs @@ -5,6 +5,7 @@ use super::{ SigQueues, SigSet, Task, Thread, ThreadId, ThreadInner, ThreadRef, }; use crate::prelude::*; +use crate::time::ThreadProfiler; #[derive(Debug)] pub struct ThreadBuilder { @@ -102,6 +103,11 @@ impl ThreadBuilder { let sig_mask = SgxRwLock::new(SigSet::new_empty()); let sig_tmp_mask = SgxRwLock::new(SigSet::new_empty()); let sig_stack = SgxMutex::new(None); + let profiler = if cfg!(feature = "syscall_timing") { + SgxMutex::new(Some(ThreadProfiler::new())) + } else { + SgxMutex::new(None) + }; let new_thread = Arc::new(Thread { task, @@ -118,6 +124,7 @@ impl ThreadBuilder { sig_mask, sig_tmp_mask, sig_stack, + profiler, }); let mut inner = new_thread.process().inner(); diff --git a/src/libos/src/process/thread/mod.rs b/src/libos/src/process/thread/mod.rs index c97d4e81..a5317730 100644 --- a/src/libos/src/process/thread/mod.rs +++ b/src/libos/src/process/thread/mod.rs @@ -8,6 +8,7 @@ use super::{ }; use crate::prelude::*; use crate::signal::{SigQueues, SigSet, SigStack}; +use crate::time::ThreadProfiler; pub use self::builder::ThreadBuilder; pub use self::id::ThreadId; @@ -36,6 +37,8 @@ pub struct Thread { sig_mask: SgxRwLock, sig_tmp_mask: SgxRwLock, sig_stack: SgxMutex>, + // System call timing + profiler: SgxMutex>, } #[derive(Debug, PartialEq, Clone, Copy)] @@ -97,6 +100,11 @@ impl Thread { &self.sig_stack } + /// Get the alternate thread performance profiler + pub fn profiler(&self) -> &SgxMutex> { + &self.profiler + } + /// Get a file from the file table. pub fn file(&self, fd: FileDesc) -> Result { self.files().lock().unwrap().get(fd) @@ -126,9 +134,27 @@ impl Thread { pub(super) fn start(&self, host_tid: pid_t) { self.sched().lock().unwrap().attach(host_tid); self.inner().start(); + + #[cfg(feature = "syscall_timing")] + self.profiler() + .lock() + .unwrap() + .as_mut() + .unwrap() + .start() + .unwrap(); } pub(super) fn exit(&self, term_status: TermStatus) -> usize { + #[cfg(feature = "syscall_timing")] + self.profiler() + .lock() + .unwrap() + .as_mut() + .unwrap() + .stop() + .unwrap(); + self.sched().lock().unwrap().detach(); // Remove this thread from its owner process @@ -171,6 +197,7 @@ impl fmt::Debug for Thread { .field("vm", self.vm()) .field("fs", self.fs()) .field("files", self.files()) + .field("profiler", self.profiler()) .finish() } } diff --git a/src/libos/src/syscall/mod.rs b/src/libos/src/syscall/mod.rs index 5c9f075b..3a898fbf 100644 --- a/src/libos/src/syscall/mod.rs +++ b/src/libos/src/syscall/mod.rs @@ -12,7 +12,7 @@ use std::convert::TryFrom; use std::ffi::{CStr, CString}; use std::io::{Read, Seek, SeekFrom, Write}; use std::ptr; -use time::{clockid_t, timespec_t, timeval_t, GLOBAL_PROFILER}; +use time::{clockid_t, timespec_t, timeval_t}; use util::log::{self, LevelFilter}; use util::mem_util::from_user::*; @@ -609,40 +609,48 @@ fn do_syscall(user_context: &mut CpuContext) { let arg4 = user_context.r8 as isize; let arg5 = user_context.r9 as isize; - // TODO: the profiler will trigger panic for syscall simulation - #[cfg(feature = "syscall_timing")] - GLOBAL_PROFILER - .lock() - .unwrap() - .syscall_enter(syscall_num) - .expect("unexpected error from profiler to enter syscall"); - let ret = Syscall::new(num, arg0, arg1, arg2, arg3, arg4, arg5).and_then(|mut syscall| { log::set_round_desc(Some(syscall.num.as_str())); trace!("{:?}", &syscall); + let syscall_num = syscall.num; // Pass user_context as an extra argument to two special syscalls that // need to modify it - if syscall.num == SyscallNum::RtSigreturn { + if syscall_num == SyscallNum::RtSigreturn { syscall.args[0] = user_context as *mut _ as isize; - } else if syscall.num == SyscallNum::HandleException { + } else if syscall_num == SyscallNum::HandleException { // syscall.args[0] == info syscall.args[1] = user_context as *mut _ as isize; - } else if syscall.num == SyscallNum::Sigaltstack { + } else if syscall_num == SyscallNum::Sigaltstack { // syscall.args[0] == new_ss // syscall.args[1] == old_ss syscall.args[2] = user_context as *const _ as isize; } - dispatch_syscall(syscall) - }); + #[cfg(feature = "syscall_timing")] + current!() + .profiler() + .lock() + .unwrap() + .as_mut() + .unwrap() + .syscall_enter(syscall_num) + .expect("unexpected error from profiler to enter syscall"); - #[cfg(feature = "syscall_timing")] - GLOBAL_PROFILER - .lock() - .unwrap() - .syscall_exit(syscall_num, ret.is_err()) - .expect("unexpected error from profiler to exit syscall"); + let ret = dispatch_syscall(syscall); + + #[cfg(feature = "syscall_timing")] + current!() + .profiler() + .lock() + .unwrap() + .as_mut() + .unwrap() + .syscall_exit(syscall_num, ret.is_err()) + .expect("unexpected error from profiler to exit syscall"); + + ret + }); let retval = match ret { Ok(retval) => retval as isize, diff --git a/src/libos/src/time/mod.rs b/src/libos/src/time/mod.rs index 22b0cbca..c5161f5e 100644 --- a/src/libos/src/time/mod.rs +++ b/src/libos/src/time/mod.rs @@ -10,7 +10,7 @@ use syscall::SyscallNum; mod profiler; pub mod up_time; -pub use profiler::GLOBAL_PROFILER; +pub use profiler::ThreadProfiler; #[allow(non_camel_case_types)] pub type time_t = i64; diff --git a/src/libos/src/time/profiler.rs b/src/libos/src/time/profiler.rs index 7edee854..30fb2510 100644 --- a/src/libos/src/time/profiler.rs +++ b/src/libos/src/time/profiler.rs @@ -1,66 +1,8 @@ use super::*; +use std::fmt::Write; -lazy_static! { - pub static ref GLOBAL_PROFILER: SgxMutex = SgxMutex::new(GlobalProfiler::new()); -} - -/// A profiler that can be used across threads. -// TODO: Use light-weight thread_local storage other than mutex -pub struct GlobalProfiler { - inner: HashMap, -} - -impl GlobalProfiler { - pub fn new() -> Self { - Self { - inner: HashMap::new(), - } - } - - pub fn thread_enter(&mut self) -> Result<()> { - let tid = current!().tid(); - if self.inner.insert(tid, ThreadProfiler::new()).is_some() { - return_errno!( - EINVAL, - "global profiler should exit the thread before entering" - ); - } - self.inner.get_mut(&tid).unwrap().start() - } - - pub fn thread_exit(&mut self) -> Result<()> { - // A thread exits by invoking exit syscall which - // will never return - self.syscall_exit(SyscallNum::Exit, false); - - let tid = current!().tid(); - - let mut exiting_profiler = self.inner.remove(&tid).ok_or_else(|| { - errno!( - EINVAL, - "global profiler should enter a thread before exit one" - ) - })?; - exiting_profiler.stop()?; - exiting_profiler.display()?; - Ok(()) - } - - pub fn syscall_enter(&mut self, syscall_num: SyscallNum) -> Result<()> { - let tid = current!().tid(); - let mut prof = self.inner.get_mut(&tid).unwrap(); - prof.syscall_enter(syscall_num) - } - - pub fn syscall_exit(&mut self, syscall_num: SyscallNum, is_err: bool) -> Result<()> { - let tid = current!().tid(); - let mut prof = self.inner.get_mut(&tid).unwrap(); - prof.syscall_exit(syscall_num, is_err) - } -} /// A profiler used inside a thread. -// TODO: add support for exception -#[derive(Clone)] +#[derive(Clone, Debug)] pub struct ThreadProfiler { syscall_data: HashMap, start_time: ProfileTime, @@ -83,7 +25,7 @@ impl ThreadProfiler { } } - fn start(&mut self) -> Result<()> { + pub fn start(&mut self) -> Result<()> { match self.status { Status::Stopped(..) => { self.status = Status::Running; @@ -96,21 +38,26 @@ impl ThreadProfiler { } } - fn stop(&mut self) -> Result<()> { - if self.status != Status::Running { - return_errno!(EINVAL, "fail to stop thread profiler"); - } - let real = time::do_gettimeofday().as_duration() - self.start_time.get_realtime().unwrap(); - + pub fn stop(&mut self) -> Result<()> { let total_cputime = time::do_thread_getcpuclock()?.as_duration() - self.start_time.get_cputime().unwrap(); + + let real = time::do_gettimeofday().as_duration() - self.start_time.get_realtime().unwrap(); let sys = self.get_syscall_total_time()?; let usr = total_cputime - sys; + self.status = Status::Stopped(TimeSummary::new(real, usr, sys)); + + self.display()?; + Ok(()) } - fn syscall_enter(&mut self, syscall_num: SyscallNum) -> Result<()> { + pub fn syscall_enter(&mut self, syscall_num: SyscallNum) -> Result<()> { + if Self::is_not_traced(syscall_num) { + return Ok(()); + } + match self.status { Status::Running => { let mut cur_time = ProfileTime::CpuTime(Default::default()); @@ -124,17 +71,28 @@ impl ThreadProfiler { .or_insert(PerfEntry::new()); Ok(()) } - _ => return_errno!( - EINVAL, - "threa profiler should be started before entering syscall" - ), + _ => { + eprintln!( + "The wrong status is {:?} the input syscall is {:?}", + self.status, syscall_num + ); + return_errno!( + EINVAL, + "thread profiler should be started before entering syscall" + ) + } } } - fn syscall_exit(&mut self, syscall_num: SyscallNum, is_err: bool) -> Result<()> { + pub fn syscall_exit(&mut self, syscall_num: SyscallNum, is_err: bool) -> Result<()> { + if Self::is_not_traced(syscall_num) { + return Ok(()); + } + match self.status { Status::InSyscall { start_cpu, num } => { if syscall_num != num { + eprintln!("current {:?} exit: {:?}", num, syscall_num); return_errno!(EINVAL, "syscall number mismatches"); } self.status = Status::Running; @@ -154,6 +112,19 @@ impl ThreadProfiler { } } + // Do not trace special system calls + // HandleException: one exception can be invoked by another exception, + // resulting in nested calling + // Exit and ExitGroup: stop would be called inside these two system calls, + // where only entering is traced + // TODO: add support for the above system calls + fn is_not_traced(syscall_num: SyscallNum) -> bool { + match syscall_num { + SyscallNum::HandleException | SyscallNum::Exit | SyscallNum::ExitGroup => true, + _ => false, + } + } + fn get_syscall_total_time(&self) -> Result { Ok(self.get_syscall_total()?.0) } @@ -176,10 +147,13 @@ impl ThreadProfiler { fn display(&self) -> Result<()> { match self.status { Status::Stopped(report) => { - // Pretty-print the Debug formatting report of the profiled thread - println!("{:#?}", report); - // Print the syscall statistics of the profiled thread - self.display_syscall_stat() + let mut s = String::new(); + write!(&mut s, "Thread {}: \n", current!().tid()); + write!(&mut s, "{:#?}\n", report); + // Print all the statitics in one function to prevent + // overlap of information from different threads + eprintln!("{}", s + &self.format_syscall_statistics()?); + Ok(()) } _ => return_errno!(EINVAL, "thread profiler can report only in stopped status"), } @@ -197,13 +171,17 @@ impl ThreadProfiler { /// SysWritev 0.40 0.000131 26 5 0 [12, 47] /// SysMprotect 0.03 0.000009 4 2 0 [4, 4] /// ------------------- ------ ----------- ----------- --------- --------- ----------- - fn display_syscall_stat(&self) -> Result<()> { - println!( - "{:<19} {:>6} {:>11} {:>11} {:>9} {:>9} {}", + fn format_syscall_statistics(&self) -> Result { + let mut s = String::new(); + + write!( + &mut s, + "{:<19} {:>6} {:>11} {:>11} {:>9} {:>9} {}\n", "syscall", "% time", "seconds", "us/call", "calls", "errors", "range(us)", ); - println!( - "{:-<19} {:-<6} {:-<11} {:-<11} {:-<9} {:-<9} {:-<11}", + write!( + s, + "{:-<19} {:-<6} {:-<11} {:-<11} {:-<9} {:-<9} {:-<11}\n", "", "", "", "", "", "", "" ); @@ -217,28 +195,31 @@ impl ThreadProfiler { for (syscall_num, entry) in syscall_data_ref { let time_percentage = entry.get_total_time().as_secs_f64() / total_time.as_secs_f64() * 100_f64; - println!( - "{:<19} {:>6.2} {:?}", + write!( + &mut s, + "{:<19} {:>6.2} {:?}\n", format!("{:?}", syscall_num), time_percentage, entry, ); } - println!( - "{:-<19} {:-<6} {:-<11} {:-<11} {:-<9} {:-<9} {:-<11}", + write!( + &mut s, + "{:-<19} {:-<6} {:-<11} {:-<11} {:-<9} {:-<9} {:-<11}\n", "", "", "", "", "", "", "" ); - println!( - "{} {:>20} {:>11.6} {:>21} {:>9}", + write!( + &mut s, + "{} {:>20} {:>11.6} {:>21} {:>9}\n", "total", "100", total_time.as_secs_f64(), total_calls, total_errors, ); - Ok(()) + Ok(s) } }