Roll src/third_party/WebKit 60624dd:2936779 (svn 202421:202423)
[chromium-blink-merge.git] / ipc / ipc_logging.cc
bloba9aa0060c08baa29841f432f8c90112b2f0d2a1a
1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
5 #include "ipc/ipc_logging.h"
7 #ifdef IPC_MESSAGE_LOG_ENABLED
8 #define IPC_MESSAGE_MACROS_LOG_ENABLED
9 #endif
11 #include "base/bind.h"
12 #include "base/bind_helpers.h"
13 #include "base/command_line.h"
14 #include "base/location.h"
15 #include "base/logging.h"
16 #include "base/single_thread_task_runner.h"
17 #include "base/strings/string_number_conversions.h"
18 #include "base/strings/string_util.h"
19 #include "base/thread_task_runner_handle.h"
20 #include "base/threading/thread.h"
21 #include "base/time/time.h"
22 #include "ipc/ipc_message_utils.h"
23 #include "ipc/ipc_sender.h"
24 #include "ipc/ipc_switches.h"
25 #include "ipc/ipc_sync_message.h"
27 #if defined(OS_POSIX)
28 #include <unistd.h>
29 #endif
31 #ifdef IPC_MESSAGE_LOG_ENABLED
33 using base::Time;
35 namespace IPC {
37 const int kLogSendDelayMs = 100;
39 // We use a pointer to the function table to avoid any linker dependencies on
40 // all the traits used as IPC message parameters.
41 LogFunctionMap* Logging::log_function_map_;
43 Logging::Logging()
44 : enabled_(false),
45 enabled_on_stderr_(false),
46 enabled_color_(false),
47 queue_invoke_later_pending_(false),
48 sender_(NULL),
49 main_thread_(base::MessageLoop::current()),
50 consumer_(NULL) {
51 #if defined(OS_WIN)
52 // getenv triggers an unsafe warning. Simply check how big of a buffer
53 // would be needed to fetch the value to see if the enviornment variable is
54 // set.
55 size_t requiredSize = 0;
56 getenv_s(&requiredSize, NULL, 0, "CHROME_IPC_LOGGING");
57 bool logging_env_var_set = (requiredSize != 0);
58 if (requiredSize <= 6) {
59 char buffer[6];
60 getenv_s(&requiredSize, buffer, sizeof(buffer), "CHROME_IPC_LOGGING");
61 if (requiredSize && !strncmp("color", buffer, 6))
62 enabled_color_ = true;
64 #else // !defined(OS_WIN)
65 const char* ipc_logging = getenv("CHROME_IPC_LOGGING");
66 bool logging_env_var_set = (ipc_logging != NULL);
67 if (ipc_logging && !strcmp(ipc_logging, "color"))
68 enabled_color_ = true;
69 #endif //defined(OS_WIN)
70 if (logging_env_var_set) {
71 enabled_ = true;
72 enabled_on_stderr_ = true;
76 Logging::~Logging() {
79 Logging* Logging::GetInstance() {
80 return base::Singleton<Logging>::get();
83 void Logging::SetConsumer(Consumer* consumer) {
84 consumer_ = consumer;
87 void Logging::Enable() {
88 enabled_ = true;
91 void Logging::Disable() {
92 enabled_ = false;
95 void Logging::OnSendLogs() {
96 queue_invoke_later_pending_ = false;
97 if (!sender_)
98 return;
100 Message* msg = new Message(
101 MSG_ROUTING_CONTROL, IPC_LOGGING_ID, Message::PRIORITY_NORMAL);
102 WriteParam(msg, queued_logs_);
103 queued_logs_.clear();
104 sender_->Send(msg);
107 void Logging::SetIPCSender(IPC::Sender* sender) {
108 sender_ = sender;
111 void Logging::OnReceivedLoggingMessage(const Message& message) {
112 std::vector<LogData> data;
113 base::PickleIterator iter(message);
114 if (!ReadParam(&message, &iter, &data))
115 return;
117 for (size_t i = 0; i < data.size(); ++i) {
118 Log(data[i]);
122 void Logging::OnSendMessage(Message* message, const std::string& channel_id) {
123 if (!Enabled())
124 return;
126 if (message->is_reply()) {
127 LogData* data = message->sync_log_data();
128 if (!data)
129 return;
131 // This is actually the delayed reply to a sync message. Create a string
132 // of the output parameters, add it to the LogData that was earlier stashed
133 // with the reply, and log the result.
134 GenerateLogData("", *message, data, true);
135 data->channel = channel_id;
136 Log(*data);
137 delete data;
138 message->set_sync_log_data(NULL);
139 } else {
140 // If the time has already been set (i.e. by ChannelProxy), keep that time
141 // instead as it's more accurate.
142 if (!message->sent_time())
143 message->set_sent_time(Time::Now().ToInternalValue());
147 void Logging::OnPreDispatchMessage(const Message& message) {
148 message.set_received_time(Time::Now().ToInternalValue());
151 void Logging::OnPostDispatchMessage(const Message& message,
152 const std::string& channel_id) {
153 if (!Enabled() ||
154 !message.sent_time() ||
155 !message.received_time() ||
156 message.dont_log())
157 return;
159 LogData data;
160 GenerateLogData(channel_id, message, &data, true);
162 if (base::MessageLoop::current() == main_thread_) {
163 Log(data);
164 } else {
165 main_thread_->task_runner()->PostTask(
166 FROM_HERE, base::Bind(&Logging::Log, base::Unretained(this), data));
170 void Logging::GetMessageText(uint32_t type, std::string* name,
171 const Message* message,
172 std::string* params) {
173 if (!log_function_map_)
174 return;
176 LogFunctionMap::iterator it = log_function_map_->find(type);
177 if (it == log_function_map_->end()) {
178 if (name) {
179 *name = "[UNKNOWN MSG ";
180 *name += base::IntToString(type);
181 *name += " ]";
183 return;
186 (*it->second)(name, message, params);
189 const char* Logging::ANSIEscape(ANSIColor color) {
190 if (!enabled_color_)
191 return "";
192 switch (color) {
193 case ANSI_COLOR_RESET:
194 return "\033[m";
195 case ANSI_COLOR_BLACK:
196 return "\033[0;30m";
197 case ANSI_COLOR_RED:
198 return "\033[0;31m";
199 case ANSI_COLOR_GREEN:
200 return "\033[0;32m";
201 case ANSI_COLOR_YELLOW:
202 return "\033[0;33m";
203 case ANSI_COLOR_BLUE:
204 return "\033[0;34m";
205 case ANSI_COLOR_MAGENTA:
206 return "\033[0;35m";
207 case ANSI_COLOR_CYAN:
208 return "\033[0;36m";
209 case ANSI_COLOR_WHITE:
210 return "\033[0;37m";
212 return "";
215 Logging::ANSIColor Logging::DelayColor(double delay) {
216 if (delay < 0.1)
217 return ANSI_COLOR_GREEN;
218 if (delay < 0.25)
219 return ANSI_COLOR_BLACK;
220 if (delay < 0.5)
221 return ANSI_COLOR_YELLOW;
222 return ANSI_COLOR_RED;
225 void Logging::Log(const LogData& data) {
226 if (consumer_) {
227 // We're in the browser process.
228 consumer_->Log(data);
229 } else {
230 // We're in the renderer or plugin processes.
231 if (sender_) {
232 queued_logs_.push_back(data);
233 if (!queue_invoke_later_pending_) {
234 queue_invoke_later_pending_ = true;
235 base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
236 FROM_HERE, base::Bind(&Logging::OnSendLogs, base::Unretained(this)),
237 base::TimeDelta::FromMilliseconds(kLogSendDelayMs));
241 if (enabled_on_stderr_) {
242 std::string message_name;
243 if (data.message_name.empty()) {
244 message_name = base::StringPrintf("[unknown type %d]", data.type);
245 } else {
246 message_name = data.message_name;
248 double receive_delay =
249 (Time::FromInternalValue(data.receive) -
250 Time::FromInternalValue(data.sent)).InSecondsF();
251 double dispatch_delay =
252 (Time::FromInternalValue(data.dispatch) -
253 Time::FromInternalValue(data.sent)).InSecondsF();
254 fprintf(stderr,
255 "ipc %s %d %s %s%s %s%s\n %18.5f %s%18.5f %s%18.5f%s\n",
256 data.channel.c_str(),
257 data.routing_id,
258 data.flags.c_str(),
259 ANSIEscape(sender_ ? ANSI_COLOR_BLUE : ANSI_COLOR_CYAN),
260 message_name.c_str(),
261 ANSIEscape(ANSI_COLOR_RESET),
262 data.params.c_str(),
263 Time::FromInternalValue(data.sent).ToDoubleT(),
264 ANSIEscape(DelayColor(receive_delay)),
265 Time::FromInternalValue(data.receive).ToDoubleT(),
266 ANSIEscape(DelayColor(dispatch_delay)),
267 Time::FromInternalValue(data.dispatch).ToDoubleT(),
268 ANSIEscape(ANSI_COLOR_RESET)
273 void GenerateLogData(const std::string& channel, const Message& message,
274 LogData* data, bool get_params) {
275 if (message.is_reply()) {
276 // "data" should already be filled in.
277 std::string params;
278 Logging::GetMessageText(data->type, NULL, &message, &params);
280 if (!data->params.empty() && !params.empty())
281 data->params += ", ";
283 data->flags += " DR";
285 data->params += params;
286 } else {
287 std::string flags;
288 if (message.is_sync())
289 flags = "S";
291 if (message.is_reply())
292 flags += "R";
294 if (message.is_reply_error())
295 flags += "E";
297 std::string params, message_name;
298 Logging::GetMessageText(message.type(), &message_name, &message,
299 get_params ? &params : NULL);
301 data->channel = channel;
302 data->routing_id = message.routing_id();
303 data->type = message.type();
304 data->flags = flags;
305 data->sent = message.sent_time();
306 data->receive = message.received_time();
307 data->dispatch = Time::Now().ToInternalValue();
308 data->params = params;
309 data->message_name = message_name;
315 #endif // IPC_MESSAGE_LOG_ENABLED