Tool to log the execution of Chrome. Initial add.

Note: this change does nothing unless order_profiling=1 is manually set in GYP defines (or EXTRA_BUILD_ARGS for cros).

When enabled, this tool is built into Chrome and makes it log its routine invocations. Every time a routine is called and if it is called for the first time (per each thread), the log is updated with current time and the address of the routine. Later, such logs can be merged (across all threads), symbolized and fed into linker ('order_text_section') so it produces binary with more optimal code layout. This must make code work faster because of better CPU cache utilization.

See more technical details in tools/cygprofile/cygprofile.cc header.

Cyg prefix is taken after the callback names in gcc that we use to hook the code: __cyg_profile_func_enter and __cyg_profile_func_exit.

More info at https://sites.google.com/a/google.com/chrome-msk/dev/boot-speed-up-effort

BUG=chromium-os:20187
TEST=units, build cros with 
declare -x EXTRA_BUILD_ARGS="order_profiling=1 linux_use_tcmalloc=0"
run it and check the log at /var/log/chrome/cyglog.*.

Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=137391

[glotov, 2011-12-02 18:35:31]

Dmitry, please have a look.

Dave, Nikita, Armand, I added you just in case you are interested. Please also
advice whom else should I send this for review to.

[Dmitry Polukhin, 2011-12-12 06:33:01]

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc
File base/cygprofile/cygprofile.cc (right):

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc#n...
base/cygprofile/cygprofile.cc:61: CygLogEntry(time_t _seconds, long int _usec,
Please don't add _ before name. Actually you can use the same names as members -
it will work.

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc#n...
base/cygprofile/cygprofile.cc:144: static std::vector<CygTlsLog*> all_logs_;
I wouldn't use statics with c-tor/d-tor in this code at all. I think it is
better to keep pointer and allocate vector dynamically and don't deallocate at
all. Otherwise you may have problem when it will be called after destruction.
Also I would use pthread_once to init such things.

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc#n...
base/cygprofile/cygprofile.cc:148: static base::Lock all_logs_mutex_;
I would use pthread primitives directly with with static inits.

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc#n...
base/cygprofile/cygprofile.cc:365: void __cyg_profile_func_enter(void* this_fn,
void* callee_unused) {
Is it called in single thread context only?

[Nikita (slow), 2011-12-12 08:53:50]

I suggest you should split this CL into 2 parts:

1. Add GYP flags order_profiling / order_text_section so that once order file is
added we may use this flags.

2. Tool that logs Chrome execution.

[Nikita (slow), 2011-12-12 08:57:51]

lgtm

Please comment why flags were added only to those gyp files (common.gypi,
chrome_exe.gypi, nacl.gypi, media.gyp, skia.gyp).

Why flag was not added to webkit.gyp etc.?

[Nikita (slow), 2011-12-12 08:59:17]

sorry, I've accidentally pushed "quck lg" button instead of "publish drafts".

http://codereview.chromium.org/8770054/diff/1/chrome/nacl.gypi
File chrome/nacl.gypi (right):

http://codereview.chromium.org/8770054/diff/1/chrome/nacl.gypi#newcode1
chrome/nacl.gypi:1: # Copyright (c) 2011 The Chromium Authors. All rights
reserved.
I've though that you were disabling NaCL during instrumentation?

[glotov, 2011-12-13 19:45:43]

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc
File base/cygprofile/cygprofile.cc (right):

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc#n...
base/cygprofile/cygprofile.cc:61: CygLogEntry(time_t _seconds, long int _usec,
Good. Will try.

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc#n...
base/cygprofile/cygprofile.cc:144: static std::vector<CygTlsLog*> all_logs_;
Good point. Worth doing.

I thought about using LazyInstance<> for that. But its comments frightened me
with the comment:
// LazyInstance uses its own struct initializer-list style static
// initialization, as base's LINKER_INITIALIZED requires a constructor and on
// some compilers (notably gcc 4.4) this still ends up needing runtime
// initialization.

Regarding pthread_once(), I heard it had a bug and thus discouraged to use in
Google code. Cannot find it now. LazyInstance<> and Singleton<> does not use
pthread_once() because of this.

On 2011/12/12 06:33:02, Dmitry Polukhin wrote:
> I wouldn't use statics with c-tor/d-tor in this code at all. I think it is
> better to keep pointer and allocate vector dynamically and don't deallocate at
> all. Otherwise you may have problem when it will be called after destruction.
> Also I would use pthread_once to init such things.

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc#n...
base/cygprofile/cygprofile.cc:148: static base::Lock all_logs_mutex_;
What do you mean?

On 2011/12/12 06:33:02, Dmitry Polukhin wrote:
> I would use pthread primitives directly with with static inits.

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc#n...
base/cygprofile/cygprofile.cc:365: void __cyg_profile_func_enter(void* this_fn,
void* callee_unused) {
What do you mean? Compiler just adds calls to this function prior every normal
function call. Despite the threads.

On 2011/12/12 06:33:02, Dmitry Polukhin wrote:
> Is it called in single thread context only?

[dpolukhin, 2011-12-14 07:10:50]

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc
File base/cygprofile/cygprofile.cc (right):

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc#n...
base/cygprofile/cygprofile.cc:148: static base::Lock all_logs_mutex_;
On 2011/12/13 19:45:43, glotov wrote:
> What do you mean?
> 
> On 2011/12/12 06:33:02, Dmitry Polukhin wrote:
> > I would use pthread primitives directly with with static inits.
> 

It is static variable with c-tor/d-tor I recommended to use pthread primitives
directly with static initializers and without destruction because you don't know
when it is safe to destruct things.

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc#n...
base/cygprofile/cygprofile.cc:365: void __cyg_profile_func_enter(void* this_fn,
void* callee_unused) {
On 2011/12/13 19:45:43, glotov wrote:
> What do you mean? Compiler just adds calls to this function prior every normal
> function call. Despite the threads.
> 
> On 2011/12/12 06:33:02, Dmitry Polukhin wrote:
> > Is it called in single thread context only?
> 

Please ignore this comment. tls_current_log is thread local so there is not
problem here.

[Nikita (slow), 2012-01-20 08:47:01]

Please create new CL that only contains support for order file as we've
discussed.

Optimized instrumentation is not a priority now as it provides 2x/3x less
speedup than existing instrumentation.

[glotov, 2012-04-05 13:50:20]

Updated. Please have a look again.

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc
File base/cygprofile/cygprofile.cc (right):

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc#n...
base/cygprofile/cygprofile.cc:148: static base::Lock all_logs_mutex_;
On 2011/12/14 07:10:51, dpolukhin wrote:
> On 2011/12/13 19:45:43, glotov wrote:
> > What do you mean?
> > 
> > On 2011/12/12 06:33:02, Dmitry Polukhin wrote:
> > > I would use pthread primitives directly with with static inits.
> > 
> 
> It is static variable with c-tor/d-tor I recommended to use pthread primitives
> directly with static initializers and without destruction because you don't
know
> when it is safe to destruct things.

Done.

http://codereview.chromium.org/8770054/diff/1/base/cygprofile/cygprofile.cc#n...
base/cygprofile/cygprofile.cc:365: void __cyg_profile_func_enter(void* this_fn,
void* callee_unused) {
On 2011/12/14 07:10:51, dpolukhin wrote:
> On 2011/12/13 19:45:43, glotov wrote:
> > What do you mean? Compiler just adds calls to this function prior every
normal
> > function call. Despite the threads.
> > 
> > On 2011/12/12 06:33:02, Dmitry Polukhin wrote:
> > > Is it called in single thread context only?
> > 
> 
> Please ignore this comment. tls_current_log is thread local so there is not
> problem here.

Done.

[Dmitry Polukhin, 2012-04-09 11:05:05]

LGTM with nit

http://codereview.chromium.org/8770054/diff/27001/build/common.gypi
File build/common.gypi (right):

http://codereview.chromium.org/8770054/diff/27001/build/common.gypi#newcode2121
build/common.gypi:2121: #                ],
Do you need these commented out lines?

[glotov, 2012-04-11 17:00:33]

Hi Brett! I need your owner approval.

http://codereview.chromium.org/8770054/diff/27001/build/common.gypi
File build/common.gypi (right):

http://codereview.chromium.org/8770054/diff/27001/build/common.gypi#newcode2121
build/common.gypi:2121: #                ],
Obsolete, removed.

On 2012/04/09 11:05:05, Dmitry Polukhin wrote:
> Do you need these commented out lines?

[brettw, 2012-04-11 23:37:10]

Would this be better in src/tools or src/chrome/tools?

[brettw, 2012-04-11 23:43:38]

Also, can you give more background? This doesn't make any sense to me: "Writes
logs containing time and address of the callback being called for the first
time."

What do you mean by "the callback"? What callback? What do you mean by "the
first time".

Why this is called "cygprofile"? Can that be explained?

[glotov, 2012-05-15 16:01:25]

Hi Brett! Sorry for the delay, it was my vacation.

I updated the description and moved profiler code to tools. Please have a look.


On 2012/04/11 23:43:38, brettw wrote:
> Also, can you give more background? This doesn't make any sense to me: "Writes
> logs containing time and address of the callback being called for the first
> time."
> 
> What do you mean by "the callback"? What callback? What do you mean by "the
> first time".
> 
> Why this is called "cygprofile"? Can that be explained?

[brettw, 2012-05-15 22:59:53]

I don't understand this well, so I'll assume you guys know what you're doing.
Owners LGTM

http://codereview.chromium.org/8770054/diff/41002/tools/cygprofile/cygprofile.cc
File tools/cygprofile/cygprofile.cc (right):

http://codereview.chromium.org/8770054/diff/41002/tools/cygprofile/cygprofile...
tools/cygprofile/cygprofile.cc:322: for (int i=0; i != buf_.size(); ++i) {
Style nit: spaces around =

http://codereview.chromium.org/8770054/diff/41002/tools/cygprofile/cygprofile...
tools/cygprofile/cygprofile.cc:344: for(unsigned int secs_to_sleep = 30;
secs_to_sleep != 0;)
Style nit: don't use unsigned here.

[glotov, 2012-05-16 10:49:14]

http://codereview.chromium.org/8770054/diff/41002/tools/cygprofile/cygprofile.cc
File tools/cygprofile/cygprofile.cc (right):

http://codereview.chromium.org/8770054/diff/41002/tools/cygprofile/cygprofile...
tools/cygprofile/cygprofile.cc:322: for (int i=0; i != buf_.size(); ++i) {
On 2012/05/15 22:59:54, brettw wrote:
> Style nit: spaces around =

Done.

http://codereview.chromium.org/8770054/diff/41002/tools/cygprofile/cygprofile...
tools/cygprofile/cygprofile.cc:344: for(unsigned int secs_to_sleep = 30;
secs_to_sleep != 0;)
On 2012/05/15 22:59:54, brettw wrote:
> Style nit: don't use unsigned here.

Done.