Improved logging of Thread creation, fork, exec, spawn, backtick.

rubinius · Aug 28, 2015 · 09e3275 · 09e3275
1 parent 8542e0a
commit 09e3275
Show file tree

Hide file tree

Showing 6 changed files with 60 additions and 20 deletions.
diff --git a/vm/builtin/system.cpp b/vm/builtin/system.cpp
@@ -467,7 +467,12 @@ namespace rubinius {
         sigaction(i, &action, NULL);
       }
 
-      utilities::logger::write("spawn: %s", exe.command());
+      CallFrame* call_frame = calling_environment->get(3);
+
+      utilities::logger::write("spawn: %s, %s, %s:%d", exe.command(),
+          state->vm()->name().c_str(),
+          call_frame->file(state)->cpp_str(state).c_str(),
+          call_frame->line(state));
 
       if(exe.argc()) {
         (void)::execvp(exe.command(), exe.argv());
@@ -586,7 +591,12 @@ namespace rubinius {
         sigaction(i, &action, NULL);
       }
 
-      utilities::logger::write("backtick: %s", exe.command());
+      CallFrame* call_frame = calling_environment->get(1);
+
+      utilities::logger::write("backtick: %s, %s, %s:%d", exe.command(),
+          state->vm()->name().c_str(),
+          call_frame->file(state)->cpp_str(state).c_str(),
+          call_frame->line(state));
 
       exec_sh_fallback(state, exe.command(), exe.command_size());
 
@@ -696,7 +706,12 @@ namespace rubinius {
       old_handlers[i] = (void*)old_action.sa_handler;
     }
 
-    utilities::logger::write("exec: %s", exe.command());
+    CallFrame* call_frame = calling_environment->get(3);
+
+    utilities::logger::write("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));
 
     if(exe.argc()) {
       (void)::execvp(exe.command(), exe.argv());
@@ -821,7 +836,13 @@ namespace rubinius {
 
       if(pid > 0) {
         state->shared().internal_threads()->after_fork_parent(state);
-        utilities::logger::write("fork: child: %d", pid);
+
+        CallFrame* call_frame = calling_environment->get(2);
+
+        utilities::logger::write("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));
       }
     }
 

diff --git a/vm/builtin/thread.cpp b/vm/builtin/thread.cpp
@@ -104,8 +104,17 @@ namespace rubinius {
     return state->vm()->thread.get()->send(state, NULL, state->symbol("__run__"));
   }
 
-  Thread* Thread::allocate(STATE, Object* self) {
-    return Thread::create(state, self, send_run);
+  Thread* Thread::allocate(STATE, Object* self, CallFrame* calling_environment) {
+    Thread* thread = Thread::create(state, self, send_run);
+
+    CallFrame* call_frame = calling_environment->get(1);
+
+    utilities::logger::write("create thread: %s, %s:%d",
+        thread->vm()->name().c_str(),
+        call_frame->file(state)->cpp_str(state).c_str(),
+        call_frame->line(state));
+
+    return thread;
   }
 
   Thread* Thread::current(STATE) {
@@ -323,18 +332,17 @@ namespace rubinius {
     RUBINIUS_THREAD_START(
         const_cast<RBX_DTRACE_CHAR_P>(vm->name().c_str()), vm->thread_id(), 0);
 
-    if(cDebugThreading) {
-      utilities::logger::debug("Thread: start thread: id: %d, pthread: %d",
-          vm->thread_id(), (unsigned int)thread_debug_self());
-    }
+    vm->thread->pid(state, Fixnum::from(gettid()));
+
+    utilities::logger::write("start thread: %s, %d, %#x",
+        vm->name().c_str(), vm->thread->pid()->to_native(),
+        (unsigned int)thread_debug_self());
 
     int stack_address = 0;
     vm->set_root_stack(reinterpret_cast<uintptr_t>(&stack_address), THREAD_STACK_SIZE);
 
     NativeMethod::init_thread(state);
 
-    vm->thread->pid(state, Fixnum::from(gettid()));
-
     // Lock the thread object and unlock it at __run__ in the ruby land.
     vm->thread->alive(state, cTrue);
     vm->thread->init_lock_.unlock();
@@ -369,18 +377,16 @@ namespace rubinius {
 
     NativeMethod::cleanup_thread(state);
 
-    if(cDebugThreading) {
-      utilities::logger::debug("Thread: exit thread: id: %d", vm->thread_id());
-    }
+    utilities::logger::write("exit thread: %s", vm->name().c_str());
 
     vm->become_unmanaged();
 
     if(vm->main_thread_p() || (!ret && vm->thread_state()->raise_reason() == cExit)) {
       state->shared().signals()->system_exit(vm->thread_state()->raise_value());
-    } else {
-      vm->set_zombie(state);
     }
 
+    vm->set_zombie(state);
+
     RUBINIUS_THREAD_STOP(
         const_cast<RBX_DTRACE_CHAR_P>(vm->name().c_str()), vm->thread_id(), 0);
 

diff --git a/vm/builtin/thread.hpp b/vm/builtin/thread.hpp
@@ -118,7 +118,7 @@ namespace rubinius {
      *  @see  kernel/bootstrap/thread.rb
      */
     // Rubinius.primitive :thread_allocate
-    static Thread* allocate(STATE, Object* self);
+    static Thread* allocate(STATE, Object* self, CallFrame* calling_environment);
 
     /**
      *  Returns the Thread object for the state.

diff --git a/vm/call_frame.hpp b/vm/call_frame.hpp
@@ -61,6 +61,19 @@ namespace rubinius {
     Object* stk[0];
 
     // ACCESS
+    CallFrame* get(int frame) {
+      CallFrame* call_frame = this;
+
+      for(int i = 0; i < frame; i++) {
+        if(CallFrame* cf = call_frame->previous) {
+          call_frame = cf;
+        } else {
+          break;
+        }
+      }
+
+      return call_frame;
+    }
 
     int ip() const {
       return ip_;

diff --git a/vm/environment.cpp b/vm/environment.cpp
@@ -105,7 +105,7 @@ namespace rubinius {
 
     check_io_descriptors();
 
-    root_vm = shared->thread_nexus()->new_vm(shared, "rbx.ruby.main");
+    root_vm = shared->thread_nexus()->new_vm(shared, "ruby.main");
     root_vm->set_main_thread();
     shared->set_root_vm(root_vm);
 

diff --git a/vm/gc/managed.cpp b/vm/gc/managed.cpp
@@ -23,7 +23,7 @@ namespace rubinius {
       name_ = std::string(name);
     } else {
       std::ostringstream thread_name;
-      thread_name << "rbx.ruby." << id_;
+      thread_name << "ruby." << id_;
       name_ = thread_name.str();
     }
   }