general/occlum
4
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Refactor performance profiler

Browse Source 
1. Add the thread profiler to Thread structure
2. Fix bugs introduced by previous commits
This commit is contained in:
He Sun 2020-06-09 11:51:30 +08:00
parent 86d11e9d44
commit ec970f0e76
6 changed files with 133 additions and 124 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

14
src/libos/src/process/task/exec.rs
View File

@ -39,25 +39,11 @@ pub fn exec(libos_tid: pid_t, host_tid: pid_t) -> Result<i32> {
// 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) => {

7
src/libos/src/process/thread/builder.rs
View File

@ -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();

27
src/libos/src/process/thread/mod.rs
View File

@ -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<SigSet>,
sig_tmp_mask: SgxRwLock<SigSet>,
sig_stack: SgxMutex<Option<SigStack>>,
// System call timing
profiler: SgxMutex<Option<ThreadProfiler>>,
}
#[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<Option<ThreadProfiler>> {
&self.profiler
}
/// Get a file from the file table.
pub fn file(&self, fd: FileDesc) -> Result<FileRef> {
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()
}
}

48
src/libos/src/syscall/mod.rs
View File

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

2
src/libos/src/time/mod.rs
View File

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

159
src/libos/src/time/profiler.rs
View File

@ -1,66 +1,8 @@
use super::*;
use std::fmt::Write;
lazy_static! {
pub static ref GLOBAL_PROFILER: SgxMutex<GlobalProfiler> = 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<pid_t, ThreadProfiler>,
}
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<SyscallNum, PerfEntry>,
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<Duration> {
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<String> {
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)
}
}