From ea22c3173541606519ddcb6da578b837a092b1c1 Mon Sep 17 00:00:00 2001 From: Andy Schwerin Date: Mon, 1 Jul 2013 14:35:03 -0400 Subject: SERVER-10084 New logging implementation. This change-set: * Introduces a new top-level directory, mongo/logger, containing most of the implementation of logging functionality formerly found in log.cpp/log.h. * Cleans up existing, unusual uses of the logging system that were not trivially compatible with the new implementation. * Replaces Logstream/Nulstream with a LogstreamBuilder object, whose destructor writes log messages. This new LogstreamBuilder is reentrant, unlike the old logging code, which was thread-safe but not reentrant. Additionally, std::endl is no longer required to terminate a log line. When a LogstreamBuilder goes out of scope, the log message gets committed. * Separates the log system into several components: a global LogManager, several LogDomains, various kinds of Appenders (e.g., SyslogAppender) and Encoders (for formatting messages). * Allows unit tests to capture and examine log output. This patch does _not_ introduce support for hierarchical log domains, or for enabling and disabling specific log domains when the server is running in a multi-threaded mode. This is future work. --- src/mongo/scripting/engine_v8.cpp | 168 ++++++++++++++++++++------------------ 1 file changed, 87 insertions(+), 81 deletions(-) (limited to 'src/mongo/scripting/engine_v8.cpp') diff --git a/src/mongo/scripting/engine_v8.cpp b/src/mongo/scripting/engine_v8.cpp index 3e61236416a..527c9b0fd5c 100644 --- a/src/mongo/scripting/engine_v8.cpp +++ b/src/mongo/scripting/engine_v8.cpp @@ -17,6 +17,7 @@ #include "mongo/scripting/engine_v8.h" +#include "mongo/base/init.h" #include "mongo/platform/unordered_set.h" #include "mongo/scripting/v8_db.h" #include "mongo/scripting/v8_utils.h" @@ -303,78 +304,77 @@ namespace mongo { template void gcCallback(v8::GCType type, v8::GCCallbackFlags flags) { - const int verbosity = 1; // log level for stat collection - if (logLevel < verbosity) - // don't collect stats unless verbose - return; - - v8::HeapStatistics stats; - v8::V8::GetHeapStatistics(&stats); - log() << "V8 GC " << _GCState::name - << " heap stats - " - << " total: " << stats.total_heap_size() - << " exec: " << stats.total_heap_size_executable() - << " used: " << stats.used_heap_size()<< " limit: " - << stats.heap_size_limit() - << endl; - } - - V8ScriptEngine::V8ScriptEngine() : - _globalInterruptLock("GlobalV8InterruptLock"), - _opToScopeMap(), - _deadlineMonitor() { - } - - V8ScriptEngine::~V8ScriptEngine() { - } - - void ScriptEngine::setup() { - if (!globalScriptEngine) { - globalScriptEngine = new V8ScriptEngine(); - } - } - - std::string ScriptEngine::getInterpreterVersionString() { - return "V8 3.12.19"; - } - - void V8ScriptEngine::interrupt(unsigned opId) { - mongo::mutex::scoped_lock intLock(_globalInterruptLock); - OpIdToScopeMap::iterator iScope = _opToScopeMap.find(opId); - if (iScope == _opToScopeMap.end()) { - // got interrupt request for a scope that no longer exists - LOG(1) << "received interrupt request for unknown op: " << opId - << printKnownOps_inlock() << endl; - return; - } - LOG(1) << "interrupting op: " << opId << printKnownOps_inlock() << endl; - iScope->second->kill(); - } - - void V8ScriptEngine::interruptAll() { - mongo::mutex::scoped_lock interruptLock(_globalInterruptLock); - for (OpIdToScopeMap::iterator iScope = _opToScopeMap.begin(); - iScope != _opToScopeMap.end(); ++iScope) { - iScope->second->kill(); - } - } - - void V8Scope::registerOpId() { - scoped_lock giLock(_engine->_globalInterruptLock); - if (_engine->haveGetCurrentOpIdCallback()) { - // this scope has an associated operation - _opId = _engine->getCurrentOpId(); - _engine->_opToScopeMap[_opId] = this; - } - else - // no associated op id (e.g. running from shell) - _opId = 0; - LOG(2) << "V8Scope " << this << " registered for op " << _opId << endl; - } - - void V8Scope::unregisterOpId() { - scoped_lock giLock(_engine->_globalInterruptLock); - LOG(2) << "V8Scope " << this << " unregistered for op " << _opId << endl; + if (!logger::globalLogDomain()->shouldLog(logger::LogSeverity::Debug(1))) + // don't collect stats unless verbose + return; + + v8::HeapStatistics stats; + v8::V8::GetHeapStatistics(&stats); + log() << "V8 GC " << _GCState::name + << " heap stats - " + << " total: " << stats.total_heap_size() + << " exec: " << stats.total_heap_size_executable() + << " used: " << stats.used_heap_size()<< " limit: " + << stats.heap_size_limit() + << endl; + } + + V8ScriptEngine::V8ScriptEngine() : + _globalInterruptLock("GlobalV8InterruptLock"), + _opToScopeMap(), + _deadlineMonitor() { + } + + V8ScriptEngine::~V8ScriptEngine() { + } + + void ScriptEngine::setup() { + if (!globalScriptEngine) { + globalScriptEngine = new V8ScriptEngine(); + } + } + + std::string ScriptEngine::getInterpreterVersionString() { + return "V8 3.12.19"; + } + + void V8ScriptEngine::interrupt(unsigned opId) { + mongo::mutex::scoped_lock intLock(_globalInterruptLock); + OpIdToScopeMap::iterator iScope = _opToScopeMap.find(opId); + if (iScope == _opToScopeMap.end()) { + // got interrupt request for a scope that no longer exists + LOG(1) << "received interrupt request for unknown op: " << opId + << printKnownOps_inlock() << endl; + return; + } + LOG(1) << "interrupting op: " << opId << printKnownOps_inlock() << endl; + iScope->second->kill(); + } + + void V8ScriptEngine::interruptAll() { + mongo::mutex::scoped_lock interruptLock(_globalInterruptLock); + for (OpIdToScopeMap::iterator iScope = _opToScopeMap.begin(); + iScope != _opToScopeMap.end(); ++iScope) { + iScope->second->kill(); + } + } + + void V8Scope::registerOpId() { + scoped_lock giLock(_engine->_globalInterruptLock); + if (_engine->haveGetCurrentOpIdCallback()) { + // this scope has an associated operation + _opId = _engine->getCurrentOpId(); + _engine->_opToScopeMap[_opId] = this; + } + else + // no associated op id (e.g. running from shell) + _opId = 0; + LOG(2) << "V8Scope " << static_cast(this) << " registered for op " << _opId << endl; + } + + void V8Scope::unregisterOpId() { + scoped_lock giLock(_engine->_globalInterruptLock); + LOG(2) << "V8Scope " << static_cast(this) << " unregistered for op " << _opId << endl; if (_engine->haveGetCurrentOpIdCallback() || _opId != 0) { // scope is currently associated with an operation id V8ScriptEngine::OpIdToScopeMap::iterator it = _engine->_opToScopeMap.find(_opId); @@ -387,12 +387,12 @@ namespace mongo { v8::Locker l(_isolate); mongo::mutex::scoped_lock cbEnterLock(_interruptLock); if (v8::V8::IsExecutionTerminating(_isolate)) { - LOG(2) << "v8 execution interrupted. isolate: " << _isolate << endl; + LOG(2) << "v8 execution interrupted. isolate: " << static_cast(_isolate) << endl; return false; } if (_pendingKill || globalScriptEngine->interrupted()) { // kill flag was set before entering our callback - LOG(2) << "marked for death while leaving callback. isolate: " << _isolate << endl; + LOG(2) << "marked for death while leaving callback. isolate: " << static_cast(_isolate) << endl; v8::V8::TerminateExecution(_isolate); return false; } @@ -405,11 +405,11 @@ namespace mongo { mongo::mutex::scoped_lock cbLeaveLock(_interruptLock); _inNativeExecution = false; if (v8::V8::IsExecutionTerminating(_isolate)) { - LOG(2) << "v8 execution interrupted. isolate: " << _isolate << endl; + LOG(2) << "v8 execution interrupted. isolate: " << static_cast(_isolate) << endl; return false; } if (_pendingKill || globalScriptEngine->interrupted()) { - LOG(2) << "marked for death while leaving callback. isolate: " << _isolate << endl; + LOG(2) << "marked for death while leaving callback. isolate: " << static_cast(_isolate) << endl; v8::V8::TerminateExecution(_isolate); return false; } @@ -422,9 +422,9 @@ namespace mongo { // Set the TERMINATE flag on the stack guard for this isolate. // This won't happen between calls to nativePrologue and nativeEpilogue(). v8::V8::TerminateExecution(_isolate); - LOG(1) << "killing v8 scope. isolate: " << _isolate << endl; + LOG(1) << "killing v8 scope. isolate: " << static_cast(_isolate) << endl; } - LOG(1) << "marking v8 scope for death. isolate: " << _isolate << endl; + LOG(1) << "marking v8 scope for death. isolate: " << static_cast(_isolate) << endl; _pendingKill = true; } @@ -438,7 +438,7 @@ namespace mongo { */ std::string V8ScriptEngine::printKnownOps_inlock() { stringstream out; - if (logLevel > 1) { + if (logger::globalLogDomain()->shouldLog(logger::LogSeverity::Debug(2))) { out << " known ops: " << endl; for(OpIdToScopeMap::iterator iSc = _opToScopeMap.begin(); iSc != _opToScopeMap.end(); ++iSc) { @@ -1665,8 +1665,10 @@ namespace mongo { // --- random utils ---- + static logger::MessageLogDomain* jsPrintLogDomain; v8::Handle V8Scope::Print(V8Scope* scope, const v8::Arguments& args) { - stringstream ss; + LogstreamBuilder builder(jsPrintLogDomain, getThreadName(), logger::LogSeverity::Log()); + std::ostream& ss = builder.stream(); v8::HandleScope handle_scope; bool first = true; for (int i = 0; i < args.Length(); i++) { @@ -1690,7 +1692,6 @@ namespace mongo { ss << *str; } ss << "\n"; - Logstream::logLockless(ss.str()); return handle_scope.Close(v8::Undefined()); } @@ -1730,4 +1731,9 @@ namespace mongo { *v8::String::Utf8Value(args[0]->ToString()))); } + MONGO_INITIALIZER(JavascriptPrintDomain)(InitializerContext*) { + jsPrintLogDomain = logger::globalLogManager()->getNamedDomain("javascriptOutput"); + return Status::OK(); + } + } // namespace mongo -- cgit v1.2.1