Skip to content

Commit

Permalink
Added more profiler functionality.
Browse files Browse the repository at this point in the history
Use -Xsystem.profiler.target=<path> to set the output path for the profiler
report. The path can optionally contain the text $PID where desired and the
process ID will be substituted. Quoting the option may be necessary to prevent
the shell from expanding $PID prematurely. For example:

  rbx -Xsystem.profiler.target='path/to/profiler_report-$PID.txt'

The fully qualified name is implemented yet because it requires an additional
data structure to properly track the components, so only the bare method name
is displayed.
brixen committed May 14, 2016
1 parent 5ef29c1 commit 0fd2bd6
Showing 10 changed files with 136 additions and 21 deletions.
1 change: 1 addition & 0 deletions core/rubinius.rb
Original file line number Diff line number Diff line change
@@ -247,6 +247,7 @@ def self.version
end
end

extra << "P" if Rubinius::PROFILER != "none"
extra << "C" if Rubinius::CONCURRENT_GC
extra << "D" if Rubinius::DEBUG_BUILD

5 changes: 5 additions & 0 deletions library/rubinius/configuration.rb
Original file line number Diff line number Diff line change
@@ -142,6 +142,11 @@
d.vm_variable "target", "none",
"Location to send diagnostics: host:port, path"
end

s.section "profiler" do |p|
p.vm_variable "target", "none",
"Location to send profiler output: path"
end
end
end

6 changes: 5 additions & 1 deletion machine/builtin/thread.cpp
Original file line number Diff line number Diff line change
@@ -328,6 +328,7 @@ namespace rubinius {
state->shared().start_console(state);
state->shared().start_metrics(state);
state->shared().start_diagnostics(state);
state->shared().start_profiler(state);

Object* klass = G(rubinius)->get_const(state, state->symbol("Loader"));
if(klass->nil_p()) {
@@ -360,6 +361,7 @@ namespace rubinius {

vm->set_stack_bounds(THREAD_STACK_SIZE);
vm->set_current_thread();
vm->set_start_time();

RUBINIUS_THREAD_START(
const_cast<RBX_DTRACE_CHAR_P>(vm->name().c_str()), vm->thread_id(), 0);
@@ -380,6 +382,8 @@ namespace rubinius {
vm->thread->join_lock_.lock();
vm->thread->stopped();

vm->report_profile(state);

memory::LockedObjects& locked_objects = state->vm()->locked_objects();
for(memory::LockedObjects::iterator i = locked_objects.begin();
i != locked_objects.end();
@@ -394,7 +398,7 @@ namespace rubinius {

NativeMethod::cleanup_thread(state);

logger::write("exit thread: %s", vm->name().c_str());
logger::write("exit thread: %s %fs", vm->name().c_str(), vm->run_time());

vm->become_unmanaged();

3 changes: 2 additions & 1 deletion machine/environment.cpp
Original file line number Diff line number Diff line change
@@ -559,7 +559,8 @@ namespace rubinius {
void Environment::halt(STATE, int exit_code) {
utilities::thread::Mutex::LockGuard guard(halt_lock_);

logger::write("exit process: %s %d", shared->pid.c_str(), exit_code);
logger::write("exit process: %s %d %fs",
shared->pid.c_str(), exit_code, shared->run_time());

if(Memory* om = state->memory()) {
if(memory::ImmixMarker* im = om->immix_marker()) {
12 changes: 8 additions & 4 deletions machine/instruments/timing.hpp
Original file line number Diff line number Diff line change
@@ -53,15 +53,19 @@ static inline uint64_t get_current_time() {

namespace timer {

static inline double time_as_double() {
return (double)get_current_time() * 1000000000;
}

const int nanoseconds = 1;
const int microseconds = 1000;
const int milliseconds = 1000000;
const int seconds = 1000000000;

static inline double time_elapsed_seconds(uint64_t start_time) {
return (double)(get_current_time() - start_time) / seconds;
}

static inline double time_as_double() {
return (double)get_current_time() * 1000000000;
}

template <int factor=milliseconds>
class StopWatch {
uint64_t& total_;
2 changes: 2 additions & 0 deletions machine/ontology.cpp
Original file line number Diff line number Diff line change
@@ -397,6 +397,8 @@ namespace rubinius {
G(rubinius)->set_const(state, "BUILD_REV", String::create(state, RBX_BUILD_REV));
G(rubinius)->set_const(state, "RELEASE_DATE", String::create(state, RBX_RELEASE_DATE));
G(rubinius)->set_const(state, "DEBUG_BUILD", RBOOL(RBX_DEBUG_BUILD));
G(rubinius)->set_const(state, "PROFILER",
String::create(state, state->shared().config.system_profiler_target.value.c_str()));
G(rubinius)->set_const(state, "CONCURRENT_GC",
RBOOL(state->shared().config.gc_immix_concurrent));
G(rubinius)->set_const(state, "LDSHARED", String::create(state, RBX_LDSHARED));
33 changes: 27 additions & 6 deletions machine/shared_state.cpp
Original file line number Diff line number Diff line change
@@ -6,7 +6,6 @@
#include "config.h"
#include "memory.hpp"
#include "environment.hpp"
#include "instruments/timing.hpp"
#include "global_cache.hpp"

#include "util/thread.hpp"
@@ -19,8 +18,12 @@
#include "builtin/array.hpp"
#include "builtin/thread.hpp"
#include "builtin/native_method.hpp"
#include "builtin/system.hpp"

#include "instruments/timing.hpp"

#include <iostream>
#include <fstream>
#include <iomanip>

namespace rubinius {
@@ -33,6 +36,9 @@ namespace rubinius {
, console_(NULL)
, metrics_(NULL)
, diagnostics_(NULL)
, profiler_path_()
, profiler_enabled_(false)
, start_time_(get_current_time())
, method_count_(1)
, class_count_(1)
, global_serial_(1)
@@ -112,6 +118,10 @@ namespace rubinius {
return threads;
}

double SharedState::run_time() {
return timer::time_elapsed_seconds(start_time_);
}

SignalThread* SharedState::start_signals(STATE) {
signals_ = new SignalThread(state, state->vm());
signals_->start(state);
@@ -155,12 +165,21 @@ namespace rubinius {
return diagnostics_;
}

void SharedState::after_fork_child(STATE) {
// For now, we disable inline debugging here. This makes inspecting
// it much less confusing.
// TODO: JIT
// config.jit_inline_debug.set("no");
void SharedState::set_profiler_path() {
profiler_path_ = config.system_profiler_target.value;
env()->expand_config_value(profiler_path_, "$PID", pid.c_str());
}

void SharedState::start_profiler(STATE) {
profiler_enabled_ =
!!config.system_profiler_target.value.compare("none");

if(profiler_enabled_) {
set_profiler_path();
}
}

void SharedState::after_fork_child(STATE) {
disable_metrics(state);

// Reinit the locks for this object
@@ -178,6 +197,8 @@ namespace rubinius {
om->after_fork_child(state);
signals_->after_fork_child(state);
console_->after_fork_child(state);

if(profiler_enabled_p()) set_profiler_path();
}

const unsigned int* SharedState::object_memory_mark_address() const {
15 changes: 15 additions & 0 deletions machine/shared_state.hpp
Original file line number Diff line number Diff line change
@@ -92,6 +92,9 @@ namespace rubinius {
CApiConstantNameMap capi_constant_name_map_;
CApiConstantHandleMap capi_constant_handle_map_;

std::string profiler_path_;
bool profiler_enabled_;
uint64_t start_time_;
uint64_t method_count_;
unsigned int class_count_;
int global_serial_;
@@ -147,6 +150,8 @@ namespace rubinius {
initialized_ = true;
}

double run_time();

ThreadNexus* thread_nexus() {
return thread_nexus_;
}
@@ -227,6 +232,16 @@ namespace rubinius {
}
}

void start_profiler(STATE);
void set_profiler_path();
std::string& profiler_path() {
return profiler_path_;
}

bool profiler_enabled_p() {
return profiler_enabled_;
}

Environment* env() const {
return env_;
}
72 changes: 64 additions & 8 deletions machine/vm.cpp
Original file line number Diff line number Diff line change
@@ -29,22 +29,22 @@
#include "builtin/jit.hpp"
#include "variable_scope.hpp"

#include "instruments/timing.hpp"

#include "config_parser.hpp"
#include "config.h"

#include "call_frame.hpp"
#include "signal.hpp"
#include "configuration.hpp"
#include "helpers.hpp"
#include "park.hpp"

#include "util/thread.hpp"

#include "park.hpp"
#include "instruments/timing.hpp"

#include <iostream>
#include <iomanip>
#include <fstream>
#include <signal.h>
#ifndef RBX_WINDOWS
#include <sys/resource.h>
@@ -89,8 +89,9 @@ namespace rubinius {
, waiting_object_(this, cNil)
, profile_(this, nil<Tuple>())
, profile_sample_count_(0)
, max_profile_entries_(15)
, min_profile_call_count_(0)
, max_profile_entries_(25)
, min_profile_sample_count_(0)
, start_time_(0)
, native_method_environment(NULL)
, custom_wakeup_(NULL)
, custom_wakeup_data_(NULL)
@@ -115,6 +116,14 @@ namespace rubinius {
delete vm;
}

void VM::set_start_time() {
start_time_ = get_current_time();
}

double VM::run_time() {
return timer::time_elapsed_seconds(start_time_);
}

void VM::set_stack_bounds(size_t size) {
void* stack_address;

@@ -261,7 +270,7 @@ namespace rubinius {
const CompiledCode* c_b = try_as<CompiledCode>(*(const Object**)(b));

if(c_a && c_b) {
return c_a->machine_code()->call_count - c_b->machine_code()->call_count;
return c_b->machine_code()->sample_count - c_a->machine_code()->sample_count;
} else if(c_a) {
return 1;
} else if(c_b) {
@@ -280,6 +289,10 @@ namespace rubinius {
CompiledCode* code = state->vm()->call_frame()->compiled_code;
code->machine_code()->sample_count++;

if(code->machine_code()->sample_count < min_profile_sample_count_) {
return;
}

Tuple* profile = profile_.get();

if(profile->nil_p()) {
@@ -296,13 +309,56 @@ namespace rubinius {

CompiledCode* pcode = try_as<CompiledCode>(profile->at(0));
if(!pcode || (pcode &&
code->machine_code()->call_count > pcode->machine_code()->call_count))
code->machine_code()->sample_count > pcode->machine_code()->sample_count))
{
profile->put(state, 0, code);
min_profile_call_count_ = code->machine_code()->call_count;
min_profile_sample_count_ = code->machine_code()->sample_count;
}
}

void VM::report_profile(STATE) {
if(!state->shared().profiler_enabled_p()) return;

Tuple* profile = profile_.get();
if(profile->nil_p()) return;

std::ofstream file;
file.open(state->shared().profiler_path());

double total_time = run_time();

file << "Profile: thread: " << thread_id()
<< ", samples: " << profile_sample_count_
<< ", sample avg time: " << (total_time / profile_sample_count_)
<< ", total time: " << total_time << "s" << std::endl;

::qsort(reinterpret_cast<void*>(profile->field), profile->num_fields(),
sizeof(intptr_t), profile_compare);

file << std::endl
<< std::setw(5) << "%"
<< std::setw(10) << "Samples"
<< " Method"
<< std::endl
<< "------------------------------------------------------------"
<< std::endl;

for(native_int i = 0; i < profile->num_fields(); i++) {
if(CompiledCode* code = try_as<CompiledCode>(profile->at(i))) {
file << std::setw(5) << std::setprecision(1) << std::fixed
<< ((double)code->machine_code()->sample_count / profile_sample_count_ * 100)
<< std::setw(10)
<< code->machine_code()->sample_count
<< " "
<< code->name()->debug_str(state)
<< std::endl;
}
}

file << std::endl;
file.close();
}

static void suspend_thread() {
static int i = 0;
static int delay[] = {
8 changes: 7 additions & 1 deletion machine/vm.hpp
Original file line number Diff line number Diff line change
@@ -147,7 +147,9 @@ namespace rubinius {
memory::TypedRoot<Tuple*> profile_;
uint64_t profile_sample_count_;
native_int max_profile_entries_;
native_int min_profile_call_count_;
native_int min_profile_sample_count_;

uint64_t start_time_;

NativeMethodEnvironment* native_method_environment;

@@ -218,6 +220,9 @@ namespace rubinius {
return shared.memory();
}

void set_start_time();
double run_time();

void raise_stack_error(STATE);

size_t stack_size() {
@@ -414,6 +419,7 @@ namespace rubinius {
void collect_maybe(STATE);

void update_profile(STATE);
void report_profile(STATE);

#define RBX_PROFILE_MAX_SHIFT 0xf
#define RBX_PROFILE_MAX_INTERVAL 0x1fff

0 comments on commit 0fd2bd6

Please sign in to comment.