Adding more detail to MessageQueue::Dispatch logging.

Adding more detail to MessageQueue::Dispatch logging.

Every message will now be traced with the location from which it was
posted, including function name, file and line number.

This CL also writes a normal LOG message when the dispatch took more
than a certain amount of time (currently 50ms).

This logging should help us identify messages that are taking
longer than expected to be dispatched.

R=pthatcher@webrtc.org, tommi@webrtc.org

Committed: https://chromium.googlesource.com/external/webrtc/+/5d97a9a05b928ac50e14a0e4d8aaa42298cad056

[Taylor Brandstetter, 2016-05-31 17:30:15]

deadbeef@webrtc.org changed reviewers:
+ pthatcher@webrtc.org, tommi@webrtc.org

[tommi, 2016-05-31 19:56:27]

almost there.  I should have thought about the RTC_ prefix before. Hope that's
not too much hassle.

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.cc
File webrtc/base/location.cc (right):

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.cc#newco...
webrtc/base/location.cc:41: os << function_name_ << '@' << file_name_ << ':' <<
line_number_;
It would be great to not need sstream.  I'm looking into whether we can build
without it, which could save hundreds of KB.

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.h
File webrtc/base/location.h (right):

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.h#newcode45
webrtc/base/location.h:45: #define FROM_HERE
FROM_HERE_WITH_EXPLICIT_FUNCTION(__FUNCTION__)
Sorry I didn't think of this before, but I think we'll have to rename the macro
to RTC_FROM_HERE.  We've had issues with other macro names such as DCHECK/CHECK
which kept causing problems and we eventually renamed them to have the RTC_
prefix.  It think it would be a good thing to include that prefix here.

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.h#newcode47
webrtc/base/location.h:47: #define
FROM_HERE_WITH_EXPLICIT_FUNCTION(function_name) \
and this one as well I guess.  You could also shorten the name to
RTC_FROM_HERE_WITH_FUNCTION, RTC_FROM_HERE_WITH_NAME, RTC_FROM_FUNCTION etc.

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/messagequeue.cc
File webrtc/base/messagequeue.cc (right):

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/messagequeue.cc#n...
webrtc/base/messagequeue.cc:474: LOG(LS_INFO) << "Message took " << diff << "ms
to dispatch. Posted from: "
LS_WARNING?

[pthatcher1, 2016-05-31 20:21:02]

lgtm, assuming you fix the thing Tommi is asking for

[tommi, 2016-06-01 12:50:55]

On 2016/05/31 20:21:02, pthatcher1 wrote:
> lgtm, assuming you fix the thing Tommi is asking for

lgtm from me as well with that fix and thanks for making the change! :)

[Taylor Brandstetter, 2016-06-02 22:38:41]

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.cc
File webrtc/base/location.cc (right):

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.cc#newco...
webrtc/base/location.cc:41: os << function_name_ << '@' << file_name_ << ':' <<
line_number_;
On 2016/05/31 19:56:27, tommi-webrtc wrote:
> It would be great to not need sstream.  I'm looking into whether we can build
> without it, which could save hundreds of KB.

What's the approved method of building a string without it?

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.h
File webrtc/base/location.h (right):

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.h#newcode45
webrtc/base/location.h:45: #define FROM_HERE
FROM_HERE_WITH_EXPLICIT_FUNCTION(__FUNCTION__)
On 2016/05/31 19:56:27, tommi-webrtc wrote:
> Sorry I didn't think of this before, but I think we'll have to rename the
macro
> to RTC_FROM_HERE.  We've had issues with other macro names such as
DCHECK/CHECK
> which kept causing problems and we eventually renamed them to have the RTC_
> prefix.  It think it would be a good thing to include that prefix here.

Definitely agree; done.

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.h#newcode47
webrtc/base/location.h:47: #define
FROM_HERE_WITH_EXPLICIT_FUNCTION(function_name) \
On 2016/05/31 19:56:27, tommi-webrtc wrote:
> and this one as well I guess.  You could also shorten the name to
> RTC_FROM_HERE_WITH_FUNCTION, RTC_FROM_HERE_WITH_NAME, RTC_FROM_FUNCTION etc.

Done.

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/messagequeue.cc
File webrtc/base/messagequeue.cc (right):

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/messagequeue.cc#n...
webrtc/base/messagequeue.cc:474: LOG(LS_INFO) << "Message took " << diff << "ms
to dispatch. Posted from: "
On 2016/05/31 19:56:27, tommi-webrtc wrote:
> LS_WARNING?

I'd prefer INFO since this is more for performance debugging than for indicating
a problem. What do you think, Peter?

[pthatcher1, 2016-06-03 00:09:31]

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/messagequeue.cc
File webrtc/base/messagequeue.cc (right):

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/messagequeue.cc#n...
webrtc/base/messagequeue.cc:474: LOG(LS_INFO) << "Message took " << diff << "ms
to dispatch. Posted from: "
On 2016/06/02 22:38:41, Taylor Brandstetter wrote:
> On 2016/05/31 19:56:27, tommi-webrtc wrote:
> > LS_WARNING?
> 
> I'd prefer INFO since this is more for performance debugging than for
indicating
> a problem. What do you think, Peter?

INFO is fine.

[tommi, 2016-06-03 05:45:11]

lgtm

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.cc
File webrtc/base/location.cc (right):

https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.cc#newco...
webrtc/base/location.cc:41: os << function_name_ << '@' << file_name_ << ':' <<
line_number_;
On 2016/06/02 22:38:41, Taylor Brandstetter wrote:
> On 2016/05/31 19:56:27, tommi-webrtc wrote:
> > It would be great to not need sstream.  I'm looking into whether we can
build
> > without it, which could save hundreds of KB.
> 
> What's the approved method of building a string without it?

sprintfn. There's also a stringbuilder class somewhere iirc.

[tommi, 2016-06-03 06:00:02]

lgtm

[Taylor Brandstetter, 2016-06-03 15:58:42]

On 2016/06/03 05:45:11, tommi-webrtc wrote:
> lgtm
> 
> https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.cc
> File webrtc/base/location.cc (right):
> 
>
https://codereview.webrtc.org/2019423006/diff/1/webrtc/base/location.cc#newco...
> webrtc/base/location.cc:41: os << function_name_ << '@' << file_name_ << ':'
<<
> line_number_;
> On 2016/06/02 22:38:41, Taylor Brandstetter wrote:
> > On 2016/05/31 19:56:27, tommi-webrtc wrote:
> > > It would be great to not need sstream.  I'm looking into whether we can
> build
> > > without it, which could save hundreds of KB.
> > 
> > What's the approved method of building a string without it?
> 
> sprintfn. There's also a stringbuilder class somewhere iirc.

How do you decide on a buffer length when the input to sprintfn is of variable
size? Do you just pick an arbitrarily large size?

[Taylor Brandstetter, 2016-06-10 21:17:39]

Description was changed from

==========
Adding more detail to MessageQueue::Dispatch logging.

Every message will now be traced with the location from which it was
posted, including function name, file and line number.

This CL also writes a normal LOG message when the dispatch took more
than a certain amount of time (currently 50ms).

This logging should help us identify messages that are taking
longer than expected to be dispatched.
==========

to

==========
Adding more detail to MessageQueue::Dispatch logging.

Every message will now be traced with the location from which it was
posted, including function name, file and line number.

This CL also writes a normal LOG message when the dispatch took more
than a certain amount of time (currently 50ms).

This logging should help us identify messages that are taking
longer than expected to be dispatched.

R=pthatcher@webrtc.org, tommi@webrtc.org

Committed:
https://chromium.googlesource.com/external/webrtc/+/5d97a9a05b928ac50e14a0e4d...
==========

[commit-bot: I haz the power, 2016-06-10 21:17:39]

Description was changed from

==========
Adding more detail to MessageQueue::Dispatch logging.

Every message will now be traced with the location from which it was
posted, including function name, file and line number.

This CL also writes a normal LOG message when the dispatch took more
than a certain amount of time (currently 50ms).

This logging should help us identify messages that are taking
longer than expected to be dispatched.

R=pthatcher@webrtc.org, tommi@webrtc.org

Committed:
https://chromium.googlesource.com/external/webrtc/+/5d97a9a05b928ac50e14a0e4d...
==========

to

==========
Adding more detail to MessageQueue::Dispatch logging.

Every message will now be traced with the location from which it was
posted, including function name, file and line number.

This CL also writes a normal LOG message when the dispatch took more
than a certain amount of time (currently 50ms).

This logging should help us identify messages that are taking
longer than expected to be dispatched.

R=pthatcher@webrtc.org, tommi@webrtc.org

Committed: https://crrev.com/5d97a9a05b928ac50e14a0e4d8aaa42298cad056
Cr-Commit-Position: refs/heads/master@{#13104}
==========

[commit-bot: I haz the power, 2016-06-10 21:17:41]

Patchset 9 (id:??) landed as
https://crrev.com/5d97a9a05b928ac50e14a0e4d8aaa42298cad056
Cr-Commit-Position: refs/heads/master@{#13104}

[Taylor Brandstetter, 2016-06-10 21:17:41]

Committed patchset #9 (id:160001) manually as
5d97a9a05b928ac50e14a0e4d8aaa42298cad056 (presubmit successful).

[Taylor Brandstetter, 2016-06-10 21:23:15]

I'm aware that this breaks the FYI bots; they should be fixed by this CL:
https://codereview.chromium.org/2037873003/