From ea7744a0da59d3033b1c02d6794142fb11ae0a0e Mon Sep 17 00:00:00 2001 From: "scottbyer@chromium.org" Date: Thu, 20 Oct 2011 19:34:43 +0000 Subject: [PATCH] More message names and some timing output for the IPC logging. With ANSI color if asked for. BUG=none TEST=none Review URL: http://codereview.chromium.org/8319023 git-svn-id: svn://svn.chromium.org/chrome/trunk/src@106541 0039d316-1c4b-4281-b951-d872f2087c98 --- ipc/ipc_logging.cc | 77 +++++++++++++++++++++++++++++++++++++---- ipc/ipc_logging.h | 15 ++++++++ ipc/ipc_message_utils.h | 4 +-- 3 files changed, 87 insertions(+), 9 deletions(-) diff --git a/ipc/ipc_logging.cc b/ipc/ipc_logging.cc index 2dbd567b282e87..f6e91c44f65bfa 100644 --- a/ipc/ipc_logging.cc +++ b/ipc/ipc_logging.cc @@ -44,6 +44,7 @@ LogFunctionMap* Logging::log_function_map_; Logging::Logging() : enabled_(false), enabled_on_stderr_(false), + enabled_color_(false), queue_invoke_later_pending_(false), sender_(NULL), main_thread_(MessageLoop::current()), @@ -55,8 +56,17 @@ Logging::Logging() size_t requiredSize = 0; getenv_s(&requiredSize, NULL, 0, "CHROME_IPC_LOGGING"); bool logging_env_var_set = (requiredSize != 0); + if (requiredSize <= 6) { + char buffer[6]; + getenv_s(&requiredSize, buffer, sizeof(buffer), "CHROME_IPC_LOGGING"); + if (requiredSize && !strncmp("color", buffer, 6)) + enabled_color_ = true; + } #else // !defined(OS_WIN) - bool logging_env_var_set = (getenv("CHROME_IPC_LOGGING") != NULL); + const char* ipc_logging = getenv("CHROME_IPC_LOGGING"); + bool logging_env_var_set = (ipc_logging != NULL); + if (ipc_logging && !strcmp(ipc_logging, "color")) + enabled_color_ = true; #endif //defined(OS_WIN) if (logging_env_var_set) { enabled_ = true; @@ -123,7 +133,7 @@ void Logging::OnSendMessage(Message* message, const std::string& channel_id) { // of the output parameters, add it to the LogData that was earlier stashed // with the reply, and log the result. data->channel = channel_id; - GenerateLogData("", *message, data); + GenerateLogData("", *message, data, true); Log(*data); delete data; message->set_sync_log_data(NULL); @@ -148,7 +158,7 @@ void Logging::OnPostDispatchMessage(const Message& message, return; LogData data; - GenerateLogData(channel_id, message, &data); + GenerateLogData(channel_id, message, &data, true); if (MessageLoop::current() == main_thread_) { Log(data); @@ -177,6 +187,42 @@ void Logging::GetMessageText(uint32 type, std::string* name, (*it->second)(name, message, params); } +const char* Logging::ANSIEscape(ANSIColor color) { + if (!enabled_color_) + return ""; + switch (color) { + case ANSI_COLOR_RESET: + return "\033[m"; + case ANSI_COLOR_BLACK: + return "\033[0;30m"; + case ANSI_COLOR_RED: + return "\033[0;31m"; + case ANSI_COLOR_GREEN: + return "\033[0;32m"; + case ANSI_COLOR_YELLOW: + return "\033[0;33m"; + case ANSI_COLOR_BLUE: + return "\033[0;34m"; + case ANSI_COLOR_MAGENTA: + return "\033[0;35m"; + case ANSI_COLOR_CYAN: + return "\033[0;36m"; + case ANSI_COLOR_WHITE: + return "\033[0;37m"; + } + return ""; +} + +Logging::ANSIColor Logging::DelayColor(double delay) { + if (delay < 0.1) + return ANSI_COLOR_GREEN; + if (delay < 0.25) + return ANSI_COLOR_BLACK; + if (delay < 0.5) + return ANSI_COLOR_YELLOW; + return ANSI_COLOR_RED; +} + void Logging::Log(const LogData& data) { if (consumer_) { // We're in the browser process. @@ -199,17 +245,33 @@ void Logging::Log(const LogData& data) { } else { message_name = data.message_name; } - fprintf(stderr, "ipc %s %d %s %s %s\n", + double receive_delay = + (Time::FromInternalValue(data.receive) - + Time::FromInternalValue(data.sent)).InSecondsF(); + double dispatch_delay = + (Time::FromInternalValue(data.dispatch) - + Time::FromInternalValue(data.sent)).InSecondsF(); + fprintf(stderr, + "ipc %s %d %s %s%s %s%s\n %18.5f %s%18.5f %s%18.5f%s\n", data.channel.c_str(), data.routing_id, data.flags.c_str(), + ANSIEscape(sender_ ? ANSI_COLOR_BLUE : ANSI_COLOR_CYAN), message_name.c_str(), - data.params.c_str()); + ANSIEscape(ANSI_COLOR_RESET), + data.params.c_str(), + Time::FromInternalValue(data.sent).ToDoubleT(), + ANSIEscape(DelayColor(receive_delay)), + Time::FromInternalValue(data.receive).ToDoubleT(), + ANSIEscape(DelayColor(dispatch_delay)), + Time::FromInternalValue(data.dispatch).ToDoubleT(), + ANSIEscape(ANSI_COLOR_RESET) + ); } } void GenerateLogData(const std::string& channel, const Message& message, - LogData* data) { + LogData* data, bool get_params) { if (message.is_reply()) { // "data" should already be filled in. std::string params; @@ -233,7 +295,8 @@ void GenerateLogData(const std::string& channel, const Message& message, flags += "E"; std::string params, message_name; - Logging::GetMessageText(message.type(), &message_name, &message, ¶ms); + Logging::GetMessageText(message.type(), &message_name, &message, + get_params ? ¶ms : NULL); data->channel = channel; data->routing_id = message.routing_id(); diff --git a/ipc/ipc_logging.h b/ipc/ipc_logging.h index 42237c7ec61e23..83b85907f41889 100644 --- a/ipc/ipc_logging.h +++ b/ipc/ipc_logging.h @@ -85,6 +85,20 @@ class IPC_EXPORT Logging { } private: + typedef enum { + ANSI_COLOR_RESET = -1, + ANSI_COLOR_BLACK, + ANSI_COLOR_RED, + ANSI_COLOR_GREEN, + ANSI_COLOR_YELLOW, + ANSI_COLOR_BLUE, + ANSI_COLOR_MAGENTA, + ANSI_COLOR_CYAN, + ANSI_COLOR_WHITE + } ANSIColor; + const char* ANSIEscape(ANSIColor color); + ANSIColor DelayColor(double delay); + friend struct DefaultSingletonTraits; Logging(); @@ -93,6 +107,7 @@ class IPC_EXPORT Logging { bool enabled_; bool enabled_on_stderr_; // only used on POSIX for now + bool enabled_color_; // only used on POSIX for now std::vector queued_logs_; bool queue_invoke_later_pending_; diff --git a/ipc/ipc_message_utils.h b/ipc/ipc_message_utils.h index 91af78701ddd6c..e151649b0c97bb 100644 --- a/ipc/ipc_message_utils.h +++ b/ipc/ipc_message_utils.h @@ -999,7 +999,7 @@ class MessageSchema { // defined in ipc_logging.cc IPC_EXPORT void GenerateLogData(const std::string& channel, const Message& message, - LogData* data); + LogData* data, bool get_params); #if defined(IPC_MESSAGE_LOG_ENABLED) @@ -1027,7 +1027,7 @@ inline void ConnectMessageAndReply(const Message* msg, Message* reply) { // output parameters at that point. Instead, save its data and log it // with the outgoing reply message when it's sent. LogData* data = new LogData; - GenerateLogData("", *msg, data); + GenerateLogData("", *msg, data, true); msg->set_dont_log(); reply->set_sync_log_data(data); }