Add trace code to track all posted tasks in message_loop.

base/tracked.h

 // Copyright (c) 2011 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 //------------------------------------------------------------------------------
 // Tracked is the base class for all tracked objects.  During construction, it
 // registers the fact that an instance was created, and at destruction time, it
 // records that event.  The instance may be tagged with a name, which is refered
 // to as its Location.  The Location is a file and line number, most
 // typically indicated where the object was constructed.  In some cases, as the
 // object's significance is refined (for example, a Task object is augmented to
 // do additonal things), its Location may be redefined to that later location.
 
 // Tracking includes (for each instance) recording the birth thread, death
 // thread, and duration of life (from construction to destruction).  All this
 // data is accumulated and filtered for review at about:objects.
 
 #ifndef BASE_TRACKED_H_
 #define BASE_TRACKED_H_
 #pragma once
 
 #include <string>
 
 #include "base/base_export.h"
+#include "base/string_piece.h"
+#include "base/stringize_macros.h"
 #include "base/time.h"
 
 #ifndef NDEBUG
 #ifndef TRACK_ALL_TASK_OBJECTS
 #define TRACK_ALL_TASK_OBJECTS
 #endif   // TRACK_ALL_TASK_OBJECTS
 #endif  // NDEBUG
 
 namespace tracked_objects {
 
 //------------------------------------------------------------------------------
 // Location provides basic info where of an object was constructed, or was
 // significantly brought to life.
 
 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.
   // All we need is *some* (any) hashing distinction.  Strings should already
   // be unique, so we don't bother with strcmp or such.
   // Use line number as the primary key (because it is fast, and usually gets us
   // 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,
              std::string* output) const;
 
   // Write function_name_ in HTML with '<' and '>' properly encoded.
   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();
 
 //------------------------------------------------------------------------------
 // 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())
 
 
 //------------------------------------------------------------------------------
 
 
 class Births;
 
 class BASE_EXPORT Tracked {
  public:
   Tracked();
   virtual ~Tracked();
 
   // Used to record the FROM_HERE location of a caller.
   void SetBirthPlace(const Location& from_here);
   const Location GetBirthPlace() const;
 
   // When a task sits around a long time, such as in a timer, or object watcher,
   // this method should be called when the task becomes active, and its
   // significant lifetime begins (and its waiting to be woken up has passed).
   void ResetBirthTime();
 
   bool MissingBirthPlace() const;
 
 #if defined(TRACK_ALL_TASK_OBJECTS)
   base::TimeTicks tracked_birth_time() const { return tracked_birth_time_; }
 #else
   base::TimeTicks tracked_birth_time() const { return base::TimeTicks::Now(); }

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

You didn't just make this change... but....

My general goal was always that when TRACK_ALL_TASK_OBJECTS was not defined, we
would effectively compile away all our code, and have zero perf impact.  I'm not
sure if anyone is really calling this method, but a much more minimal
implementation would be:

return base::TimeTicks::TimeTicks();

Or even NOT_REACHED(), or CHECK(false);

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

I believe ajwong is considering removing this class altogether.

 #endif  // defined(TRACK_ALL_TASK_OBJECTS)
 
   // Returns null if SetBirthPlace has not been called.
   const void* get_birth_program_counter() const {
     return birth_program_counter_;
   }
 
  private:
 #if defined(TRACK_ALL_TASK_OBJECTS)
 
   // Pointer to instance were counts of objects with the same birth location
   // (on the same thread) are stored.
   Births* tracked_births_;
   // The time this object was constructed.  If its life consisted of a long
   // waiting period, and then it became active, then this value is generally
   // reset before the object begins it active life.
   base::TimeTicks tracked_birth_time_;
 
 #endif  // defined(TRACK_ALL_TASK_OBJECTS)
 
   const void* birth_program_counter_;
 
   DISALLOW_COPY_AND_ASSIGN(Tracked);
 };
 
 }  // namespace tracked_objects
 
 #endif  // BASE_TRACKED_H_