Skip to content
Permalink

Comparing changes

Choose two branches to see what’s changed or to start a new pull request. If you need to, you can also or learn more about diff comparisons.

Open a pull request

Create a new pull request by comparing changes across two branches. If you need to, you can also . Learn more about diff comparisons here.
base repository: rubinius/rubinius
Failed to load repositories. Confirm that selected base ref is valid, then try again.
Loading
base: d49a89ad5e68
Choose a base ref
...
head repository: rubinius/rubinius
Failed to load repositories. Confirm that selected head ref is valid, then try again.
Loading
compare: 33eb75044c26
Choose a head ref
  • 4 commits
  • 13 files changed
  • 1 contributor

Commits on Jun 8, 2016

  1. Added config for logging Thread, Fiber events.

    The follow configuration options control whether to log lifetime events (eg create, exit)
    for Thread and Fiber, and whether to log finalizer activity.
    
      -Xmachine.thread.log.lifetime (default true)
      -Xmachine.thread.log.finalizer (default false)
      -Xmachine.fiber.log.lifetime (default true)
      -Xmachine.fiber.log.finalizer (default false)
    brixen committed Jun 8, 2016
    Copy the full SHA
    0a30219 View commit details
  2. Recreate logger instance after fork().

    During a fork() event, it's possible for another thread to be writing to the
    logger and the logger mutex to be in an unknown state in the child. So, we
    recreate the logger post fork() in the child. This also simplifies ensuring
    that eg the PID stamp is correct.
    brixen committed Jun 8, 2016
    Copy the full SHA
    65e453b View commit details
  3. Added config option for logging process lifetime events.

    During the process lifetime, various events like spawn, fork, exec, etc may be
    logged. The following option allows turning off those events;
    
      -Xsystem.log.lifetime
    
    This may be useful to filter information from the logs when running
    particularly noisy processes that do a lot of subprocess activity. The default
    state, however, is to log these events because they can be extremely helpful
    when debugging issue.
    brixen committed Jun 8, 2016
    Copy the full SHA
    a47c268 View commit details
  4. Fixed finalizer deadlock.

    The finalizer thread is now running as unmanaged phase while doing list
    manipulations and the transition to managed phase is done by the individual
    finalizer object depending on whether it is a managed or unmanaged finalizer.
    brixen committed Jun 8, 2016
    Copy the full SHA
    33eb750 View commit details
19 changes: 19 additions & 0 deletions library/rubinius/configuration.rb
Original file line number Diff line number Diff line change
@@ -65,11 +65,27 @@

f.vm_variable "stack_size", 512 * 1024,
"The size in bytes of the Fiber's stack"

f.section "log" do |l|
l.vm_variable "lifetime", true,
"Log events during the Fiber's lifetime"

l.vm_variable "finalizer", false,
"Log finalizer execution"
end
end

m.section "thread" do |t|
t.vm_variable "stack_size", 4 * 1024 * 1024,
"The size in bytes of the Thread's stack"

t.section "log" do |l|
l.vm_variable "lifetime", true,
"Log events during the Thread's lifetime"

l.vm_variable "finalizer", false,
"Log finalizer execution"
end
end

m.vm_variable "stack_cushion", 4096,
@@ -116,6 +132,9 @@

l.vm_variable "level", "warn",
"Logging level: fatal, error, warn, info, debug"

l.vm_variable "lifetime", true,
"Log events during the process lifetime"
end

s.section "metrics" do |m|
37 changes: 22 additions & 15 deletions machine/builtin/fiber.cpp
Original file line number Diff line number Diff line change
@@ -82,9 +82,11 @@ namespace rubinius {
fib->dead(cTrue);
fib->set_call_frame(state, 0);

logger::write("fiber: exit: %s, %d, %fs",
fib->thread_name()->c_str(state),
fib->fiber_id()->to_native(), fib->run_time());
if(state->shared().config.machine_fiber_log_lifetime.value) {
logger::write("fiber: exit: %s, %d, %fs",
fib->thread_name()->c_str(state),
fib->fiber_id()->to_native(), fib->run_time());
}

Fiber* dest = fib->prev();

@@ -130,20 +132,22 @@ namespace rubinius {
fib->stack_size(state, size);
}

if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
std::ostringstream source;
if(state->shared().config.machine_fiber_log_lifetime.value) {
if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
std::ostringstream source;

source << call_frame->file(state)->cpp_str(state).c_str()
<< ":" << call_frame->line(state);
source << call_frame->file(state)->cpp_str(state).c_str()
<< ":" << call_frame->line(state);

logger::write("fiber: new: %s, %d, %s",
fib->thread_name()->c_str(state),
fib->fiber_id()->to_native(), source.str().c_str());
logger::write("fiber: new: %s, %d, %s",
fib->thread_name()->c_str(state),
fib->fiber_id()->to_native(), source.str().c_str());

fib->source(state, String::create(state, source.str().c_str()));
} else {
logger::write("fiber: new: %s, %d",
fib->thread_name()->c_str(state), fib->fiber_id()->to_native());
fib->source(state, String::create(state, source.str().c_str()));
} else {
logger::write("fiber: new: %s, %d",
fib->thread_name()->c_str(state), fib->fiber_id()->to_native());
}
}

state->vm()->metrics().system.fibers_created++;
@@ -318,7 +322,10 @@ namespace rubinius {

void Fiber::finalize(STATE, Fiber* fib) {
#ifdef RBX_FIBER_ENABLED
logger::write("finalizer: fiber: %ld", (intptr_t)fib);
if(state->shared().config.machine_fiber_log_finalizer.value) {
logger::write("fiber: finalizer: %s, %d",
fib->thread_name()->c_str(state), fib->fiber_id()->to_native());
}

if(!fib->data()) return;
fib->data()->orphan(state);
104 changes: 58 additions & 46 deletions machine/builtin/system.cpp
Original file line number Diff line number Diff line change
@@ -381,13 +381,13 @@ namespace rubinius {

static int fork_exec(STATE, int errors_fd) {
state->vm()->thread_nexus()->waiting_phase(state->vm());

std::lock_guard<std::mutex> guard(state->vm()->thread_nexus()->fork_mutex());
state->vm()->thread_nexus()->lock(state->vm());

state->shared().machine_threads()->before_fork_exec(state);
state->memory()->set_interrupt();

state->vm()->thread_nexus()->lock(state->vm());

// If execvp() succeeds, we'll read EOF and know.
fcntl(errors_fd, F_SETFD, FD_CLOEXEC);

@@ -396,9 +396,10 @@ namespace rubinius {
state->vm()->thread_nexus()->unlock();

if(pid == 0) {
logger::reset_lock();
// We're in the child...
state->vm()->after_fork_child(state);
} else if(pid > 0) {
// We're in the parent...
state->shared().machine_threads()->after_fork_exec_parent(state);
}

@@ -483,16 +484,18 @@ namespace rubinius {

close(errors[1]);

if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
logger::write("process: spawn: %d: %s, %s, %s:%d",
pid, exe.command(),
state->vm()->name().c_str(),
call_frame->file(state)->cpp_str(state).c_str(),
call_frame->line(state));
} else {
logger::write("process: spawn: %d: %s, %s",
pid, exe.command(),
state->vm()->name().c_str());
if(state->shared().config.system_log_lifetime.value) {
if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
logger::write("process: spawn: %d: %s, %s, %s:%d",
pid, exe.command(),
state->vm()->name().c_str(),
call_frame->file(state)->cpp_str(state).c_str(),
call_frame->line(state));
} else {
logger::write("process: spawn: %d: %s, %s",
pid, exe.command(),
state->vm()->name().c_str());
}
}

int error_no = 0;
@@ -603,16 +606,18 @@ namespace rubinius {
close(errors[1]);
close(output[1]);

if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
logger::write("process: backtick: %d: %s, %s, %s:%d",
pid, exe.command(),
state->vm()->name().c_str(),
call_frame->file(state)->cpp_str(state).c_str(),
call_frame->line(state));
} else {
logger::write("process: backtick: %d: %s, %s",
pid, exe.command(),
state->vm()->name().c_str());
if(state->shared().config.system_log_lifetime.value) {
if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
logger::write("process: backtick: %d: %s, %s, %s:%d",
pid, exe.command(),
state->vm()->name().c_str(),
call_frame->file(state)->cpp_str(state).c_str(),
call_frame->line(state));
} else {
logger::write("process: backtick: %d: %s, %s",
pid, exe.command(),
state->vm()->name().c_str());
}
}

int error_no = 0;
@@ -682,26 +687,30 @@ namespace rubinius {
}

Object* System::vm_exec(STATE, String* path, Array* args) {
state->vm()->thread_nexus()->waiting_phase(state->vm());
std::lock_guard<std::mutex> guard(state->vm()->thread_nexus()->exec_mutex());

/* Setting up the command and arguments may raise an exception so do it
* before everything else.
*/
ExecCommand exe(state, path, args);

if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
logger::write("process: exec: %s, %s, %s:%d", exe.command(),
state->vm()->name().c_str(),
call_frame->file(state)->cpp_str(state).c_str(),
call_frame->line(state));
} else {
logger::write("process: exec: %s, %s", exe.command(),
state->vm()->name().c_str());
if(state->shared().config.system_log_lifetime.value) {
if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
logger::write("process: exec: %s, %s, %s:%d", exe.command(),
state->vm()->name().c_str(),
call_frame->file(state)->cpp_str(state).c_str(),
call_frame->line(state));
} else {
logger::write("process: exec: %s, %s", exe.command(),
state->vm()->name().c_str());
}
}

// From this point, we are serialized.
utilities::thread::SpinLock::LockGuard guard(state->shared().env()->fork_exec_lock());

state->shared().machine_threads()->before_exec(state);

state->vm()->thread_nexus()->lock(state->vm());

void* old_handlers[NSIG];

/* Reset all signal handlers to the defaults, so any we setup in Rubinius
@@ -741,10 +750,13 @@ namespace rubinius {
sigaction(i, &action, NULL);
}

state->vm()->thread_nexus()->unlock();

state->shared().machine_threads()->after_exec(state);

/* execvp() returning means it failed. */
Exception::raise_errno_error(state, "execvp(2) failed", erno);

return NULL;
}

@@ -826,13 +838,13 @@ namespace rubinius {
return force_as<Fixnum>(Primitives::failure());
#else
state->vm()->thread_nexus()->waiting_phase(state->vm());

std::lock_guard<std::mutex> guard(state->vm()->thread_nexus()->fork_mutex());
state->vm()->thread_nexus()->lock(state->vm());

state->shared().machine_threads()->before_fork(state);
state->memory()->set_interrupt();

state->vm()->thread_nexus()->lock(state->vm());

int pid = ::fork();

state->vm()->thread_nexus()->unlock();
@@ -841,19 +853,19 @@ namespace rubinius {
// We're in the parent...
state->shared().machine_threads()->after_fork_parent(state);

if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
logger::write("process: fork: child: %d, %s, %s:%d", pid,
state->vm()->name().c_str(),
call_frame->file(state)->cpp_str(state).c_str(),
call_frame->line(state));
} else {
logger::write("process: fork: child: %d, %s", pid,
state->vm()->name().c_str());
if(state->shared().config.system_log_lifetime.value) {
if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
logger::write("process: fork: child: %d, %s, %s:%d", pid,
state->vm()->name().c_str(),
call_frame->file(state)->cpp_str(state).c_str(),
call_frame->line(state));
} else {
logger::write("process: fork: child: %d, %s", pid,
state->vm()->name().c_str());
}
}
} else if(pid == 0) {
// We're in the child...
logger::reset_lock();

state->vm()->after_fork_child(state);

state->vm()->thread->init_lock();
56 changes: 34 additions & 22 deletions machine/builtin/thread.cpp
Original file line number Diff line number Diff line change
@@ -102,6 +102,10 @@ namespace rubinius {
}

void Thread::finalize(STATE, Thread* thread) {
if(state->shared().config.machine_thread_log_finalizer.value) {
logger::write("thread: finalizer: %s", thread->vm()->name().c_str());
}

thread->finalize_instance(state);
}

@@ -155,18 +159,20 @@ namespace rubinius {
thread->stack_size(state, size);
}

if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
std::ostringstream source;
if(state->shared().config.machine_thread_log_lifetime.value) {
if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
std::ostringstream source;

source << call_frame->file(state)->cpp_str(state).c_str()
<< ":" << call_frame->line(state);
source << call_frame->file(state)->cpp_str(state).c_str()
<< ":" << call_frame->line(state);

logger::write("thread: new: %s, %s",
thread->vm()->name().c_str(), source.str().c_str());
logger::write("thread: new: %s, %s",
thread->vm()->name().c_str(), source.str().c_str());

thread->source(state, String::create(state, source.str().c_str()));
} else {
logger::write("thread: new: %s", thread->vm()->name().c_str());
thread->source(state, String::create(state, source.str().c_str()));
} else {
logger::write("thread: new: %s", thread->vm()->name().c_str());
}
}

if(!thread->send(state, state->symbol("initialize"), args, block, true)) {
@@ -188,18 +194,20 @@ namespace rubinius {
thread->stack_size(state, size);
}

if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
std::ostringstream source;
if(state->shared().config.machine_thread_log_lifetime.value) {
if(CallFrame* call_frame = state->vm()->get_noncore_frame(state)) {
std::ostringstream source;

source << call_frame->file(state)->cpp_str(state).c_str()
<< ":" << call_frame->line(state);
source << call_frame->file(state)->cpp_str(state).c_str()
<< ":" << call_frame->line(state);

logger::write("thread: start: %s, %s",
thread->vm()->name().c_str(), source.str().c_str());
logger::write("thread: start: %s, %s",
thread->vm()->name().c_str(), source.str().c_str());

thread->source(state, String::create(state, source.str().c_str()));
} else {
logger::write("thread: start: %s", thread->vm()->name().c_str());
thread->source(state, String::create(state, source.str().c_str()));
} else {
logger::write("thread: start: %s", thread->vm()->name().c_str());
}
}

if(!thread->send(state, state->symbol("__thread_initialize__"), args, block, true)) {
@@ -397,9 +405,11 @@ namespace rubinius {

vm->thread->pid(state, Fixnum::from(gettid()));

logger::write("thread: run: %s, %d, %#x",
vm->name().c_str(), vm->thread->pid()->to_native(),
(unsigned int)thread_debug_self());
if(state->shared().config.machine_thread_log_lifetime.value) {
logger::write("thread: run: %s, %d, %#x",
vm->name().c_str(), vm->thread->pid()->to_native(),
(unsigned int)thread_debug_self());
}

NativeMethod::init_thread(state);

@@ -427,7 +437,9 @@ namespace rubinius {

NativeMethod::cleanup_thread(state);

logger::write("thread: exit: %s %fs", vm->name().c_str(), vm->run_time());
if(state->shared().config.machine_thread_log_lifetime.value) {
logger::write("thread: exit: %s %fs", vm->name().c_str(), vm->run_time());
}

vm->unmanaged_phase();

Loading