Add trace code to track all posted tasks in message_loop.

base/tracked.h

Index: base/tracked.h
diff --git a/base/tracked.h b/base/tracked.h
index 3c73519c6c650d051423918a59892763bcdf7fba..6745f51cc989326f0b18263e60e2b6485d98c75d 100644
--- a/base/tracked.h
+++ b/base/tracked.h
@@ -22,6 +22,8 @@
 #include <string>
 
 #include "base/base_export.h"
+#include "base/string_piece.h"
+#include "base/stringize_macros.h"
 #include "base/time.h"
 
 #ifndef NDEBUG
@@ -38,15 +40,15 @@ namespace tracked_objects {
 
 class BASE_EXPORT Location {
  public:
-  // Constructor should be called with a long-lived char*, such as __FILE__.
-  // It assumes the provided value will persist as a global constant, and it
-  // will not make a copy of it.
-  Location(const char* function_name,
-           const char* file_name,
-           int line_number,
+  // Constructor should be called with a long-lived char*. It assumes the
+  // provided value will persist as a global constant, and it will not make a
+  // copy of it.
+  // |file_line| is formatted as "FILE:LINE".
+  Location(const char* file_line,
+           const char* function_name,

[jbates, 2011/08/31 00:40:48]

I really wanted this to be "FILE:LINE:FUNCTION" to remove another pointer.
Unfortunately, __FUNCTION__ is not expanded by the preprocessor, so it can not
be concatenated at preprocess time.

[jar (doing other things), 2011/09/01 18:17:51]

There is a memory cost of having FILE:LINE, as it causes unique static strings
to be allocated. The original form only caused one static string per file that
posted a task.  This code causes the compounded string to be allocated.

You say you wanted to reduce this to one pointer, and that is presumably to make
each element in your history queue smaller.  

Having the extra data in each pointed to object would mean more static memory
allocated.  You should look closely at the tradeoff, for the queue size you
select.

I'm not fully clear about a strong advantage one way or the other, and I'd like
to understand the justification for the choice you made.

The distinctive strings also provide for a faster matching system, but I don't
know if that was a bottleneck (perf issue).  It may be even less of an issue if
you don't have to do matching (which I don't think needs to be done if you just
queue the history, rather than tally stats in real time).

On 2011/08/31 00:40:48, jbates wrote:

[jbates, 2011/09/01 23:01:52]

The only purpose I had in mind of merging these is to reduce the footprint of
Location. Part of this change adds Location to a frequently used object
PendingTask. We pass these objects around in a lot of places, so I thought it
would be a worthwhile tradeoff to slightly increase static memory. Originally I
thought I could remove the FUNCTION pointer as well (ie: it made more sense when
I thought I was cutting the size in half).

This change isn't required, but I think it is a slight improvement.

            const void* program_counter);
 
-  // Provide a default constructor for easy of debugging.
+  // Default constructor initializes to "Unknown:-1", "Unknown", NULL.
   Location();
 
   // Comparison operator for insertion into a std::map<> hash tables.
@@ -56,16 +58,14 @@ class BASE_EXPORT Location {
   // a difference), and then pointers as secondary keys (just to get some
   // distinctions).
   bool operator < (const Location& other) const {
-    if (line_number_ != other.line_number_)
-      return line_number_ < other.line_number_;
-    if (file_name_ != other.file_name_)
-      return file_name_ < other.file_name_;
-    return function_name_ < other.function_name_;
+    return file_line_ < other.file_line_;

[jbates, 2011/08/31 00:40:48]

If file_line is the same, function is the same, so no point in comparing
function.

[jar (doing other things), 2011/09/01 18:17:51]

I think this is not true when templates are involed.  The function name can
vary, even if the file and line number are the same.  I think it is a mistake to
change this code.  Function name comparison is needed.

On 2011/08/31 00:40:48, jbates wrote:

[jbates, 2011/09/01 23:01:52]

OK, I'll add it back in. In linux/gcc, what I see is the undecorated method name
without template info, but it looks like some compilers may include template
info. Of course, __FUNCTION__ is non-standard, so if code depends on consistent
behavior here we should just remove __FUNCTION__ from Location.

   }
 
-  const char* function_name()   const { return function_name_; }
-  const char* file_name()       const { return file_name_; }
-  int line_number()             const { return line_number_; }
+  // Get long-lived file_line string "FILE:LINE".
+  const char* file_line() const { return file_line_; }
+  const base::StringPiece file_name() const;
+  int line_number() const;
+  const base::StringPiece function_name() const;
   const void* program_counter() const { return program_counter_; }
 
   void Write(bool display_filename, bool display_function_name,
@@ -75,10 +75,9 @@ class BASE_EXPORT Location {
   void WriteFunctionName(std::string* output) const;
 
  private:
-  const char* const function_name_;
-  const char* const file_name_;
-  const int line_number_;
-  const void* const program_counter_;
+  const char* file_line_;
+  const char* function_name_;
+  const void* program_counter_;

[jar (doing other things), 2011/09/01 18:17:51]

Why did you decide these didn't need to be constant pointers as well as pointers
to constant data?

[jbates, 2011/09/01 23:01:52]

operator= doesn't work if these pointers can't be set. Was there some reason to
prevent use of operator=?

[jar (doing other things), 2011/09/03 00:26:33]

I think it made it clear that the object was not going to change. I'm surprised
you were changing the internals.  Conceptually, I thought of a Location as a
constant, no different from "line 7."  


On 2011/09/01 23:01:52, jbates wrote:

[jbates, 2011/09/03 01:11:41]

I see. I find it useful to be able to copy Location, for example if a class is
tracking the last Location it was called from, it would code:
obj.location_ = posted_from;

That only works with this change.

 };
 
 BASE_EXPORT const void* GetProgramCounter();
@@ -86,11 +85,9 @@ BASE_EXPORT const void* GetProgramCounter();
 //------------------------------------------------------------------------------
 // Define a macro to record the current source location.
 
-#define FROM_HERE tracked_objects::Location(                                   \
-    __FUNCTION__,                                                              \
-    __FILE__,                                                                  \
-    __LINE__,                                                                  \
-    tracked_objects::GetProgramCounter())                                      \
+#define FROM_HERE tracked_objects::Location( \

[jar (doing other things), 2011/09/03 00:26:33]

I'm not sure how this happened... but the goal is to have zero perf impact when
we're not tracking objects, such as in a release build.  Toward that end, I
historically defined stuff like FROM_HERE (when not tracking) to be something
with constant strings and values, so there would be no chance the compile would
waste time/space calculating anything.  In addition, I built the constructors to
ignore their arguments, further ensuring no possible impact.  

What happened to that plan/philosophy?  Do you know??

[jbates, 2011/09/03 01:11:41]

I don't know the history of this code. The use cases I've seen are pretty heavy
weight - creating and enqueuing tasks mostly. FROM_HERE is passing and storing
three pointers (not sure the platform specifics of GetProgramCounter, but I'd
guess it's a simple register access). In comparison to the use cases, I don't
think that's too much overhead for enabling performance analysis in our
release/official builds. We can extract incredibly useful information from end
user traces.

[jar (doing other things), 2011/09/15 16:26:39]

Can you clarify how this is used? Is it sent up as part of crash dumps?  If not,
then I don't see how we'd justify much of any cost in an official build.

On 2011/09/03 01:11:41, jbates wrote:

[jbates, 2011/09/15 16:48:33]

Now that we have about:tracing in the official build, we have been able to
quickly solve multiple performance bugs reported by end users. Typical scenario:
the user reports a bug, we ask for a trace, and then we analyze the trace.
Without showing all tasks, we may miss a critical reason for a frame hitch. The
cost is 2 pointers in PendingTask. If there were 100s of PendingTasks pending,
it would only be a few KB of additional memory usage.

+    __FILE__ ":" STRINGIZE(__LINE__), __FUNCTION__, \

[jar (doing other things), 2011/09/01 18:17:51]

As mentioned, this will notably increase memory utilization for the static
strings.  It is not clear this is a positive tradeoff.

[jbates, 2011/09/01 23:01:52]

I compared release builds with and without this CL, and found that the data size
is identical and bss size is up by 32 bytes.

[jar (doing other things), 2011/09/03 00:26:33]

hmmm... the "cost" will appear in each file where there is more than one
PostTask. In that case, the file name (which seems to include the path relative
to some src root), will be replicated.  I guess the benefit will be that only a
pair of parameters (two pointers) can be used instead of a triplet (two pointers
and an int). I'm more than amazed that the difference is 32 bytes.

Was there less inlining?  Am I missing something??

On 2011/09/01 23:01:52, jbates wrote:

[jbates, 2011/09/03 01:11:41]

code/text size is separate, and it does go up by 80KB with this change as I
mentioned, but these strings aren't stored in the text section. The BSS size
went up 32 bytes, but that's irrelevant because that also wouldn't include these
strings (BSS is alloc'd and zero'd at runtime). I expected this change to
increase the size of the data section, but maybe the linker was being dumb
before and not merging equal strings. In any case, there aren't many files with
lots of FROM_HEREs so I think we're OK.

+    tracked_objects::GetProgramCounter())
 
 
 //------------------------------------------------------------------------------