Closed Bug 480735 Opened 15 years ago Closed 14 years ago

Startup timeline

Categories

(Core :: General, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla1.9.3a5

People

(Reporter: vlad, Assigned: vlad)

References

(Blocks 2 open bugs)

Details

(Keywords: dev-doc-needed, Whiteboard: [ts])

Attachments

(5 files, 29 obsolete files)

4.71 KB, patch
wtc
: review+
gal
: review+
Details | Diff | Splinter Review
18.63 KB, text/plain
Details
40.32 KB, patch
Details | Diff | Splinter Review
2.34 KB, text/plain
Details
14.18 KB, patch
benjamin
: review+
Details | Diff | Splinter Review
Attached patch startup-instrument.patch (obsolete) — Splinter Review
The attached patch generates a timeline of a bunch of events during startup, focusing on the time between XRE_main start and calling Run().  Bugs resulting from this data should be marked as blocking this bug.
Attached patch startup-instrument.patch (obsolete) — Splinter Review
Unbitrotted the patch - builds on trunk (as of today)
Attachment #364702 - Attachment is obsolete: true
Assignee: nobody → ddahl
WIP - saving work. Starting to figure out the best way to make this part of the trunk tree
Attachment #379970 - Attachment is obsolete: true
Still a work in progress...

I added #ifdef NS_FUNCTION_TIMER, then I created some macros to wrap the ft init and ft.Mark as well as fta init and fta.Mark

I am not sure how to set up an ac_add_option or make argument to define NS_FUNCTION_TIMER
Attachment #387534 - Attachment is obsolete: true
Attachment #387688 - Flags: review?(vladimir)
ddahl:  Have you looked at the timeline code that already existed, out of curiosity?
brian: no, I have not. Is there a bug that describes it?
The existing timeline stuff is pretty grungry code and pretty hard to maintain; it also doesn't easily help with "tell me how long this function takes", which is the goal here.  Eventually the idea is to have this always built and enabled.
ddahl:  No clue if it's documented anywhere.

vlad:  Can we gut the old stuff, then?
vlad: I added this to the end of xpcom/glue/Makefile.in:

DEFINES += -DNS_FUNCTION_TIMER

It does not seem like nsFunctionTimer is ever getting compiled now.

I commented out the #ifdef NS_FUNCTION_TIMER and recompiled, but it does not seem to create the macros defined in nsFunctionTimer.h

I also added some blatant syntax errors in nsFunctionTimer.h, but they were not caught. 

sorry for the noob questions. 

Not sure what I am doing wrong.
Things that need nailing down:

1. Figure out how to establish 'NS_FUNCTION_TIMER' as something that can be defined globally to turn on the "active macros" for this patch. - perhaps ted can show me how?

2. Clean up the JS implementation and make a globally-defined JS function that is a noop if the NS_FUNCTION_TIMER is not defined. (this is not as clean as the macro approach in C++land)

3. open a related bug that tracks the development of the python "output collection" and JS "visualization" via similie-widgets, example is here: http://mozilla.ddahl.com/startup/timeline-similie.html
Blocks: 503605
Comment on attachment 387688 [details] [diff] [review]
Added macros that wrap the nsFuntionTimer functionality

To get the define in, you need to add it to configure.in, as a new AC_ARG_ENABLE... search for AC_DEFINE and see how it's used in some others.


Some comments:

>+#ifdef NS_FUNCTION_TIMER
>+
>+#define NS_FUNCTION_TIMER_INIT(description, ...) nsFunctionTimer ft(description, __VA_ARGS__)
>+#define NS_FUNCTION_TIMER_MARK(description, ...) ft.Mark(description, __VA_ARGS__)

Can't call this object ft all the time in a macro... better would be:

#define NS_FUNCTION_TIMER_DECLARE(_name, _desc, ...)  nsFunctionTimer _name(_desc, __VA_ARGS__)

etc.. that is, explicitly declare the name.

Maybe some convenience functions though that would declare a single timer with the function name.. something like

#define NS_FUNCTION_TIME_THIS  nsFunctionTimer ft__this(__FUNCTION__)
I've asked around about this error, no one seems to know what is happening.

nsIOService.cpp
/home/ddahl/code/moz/mozilla-central/mozilla/netwerk/base/src/nsIOService.cpp:199:47: warning: ISO C99 requires rest arguments to be used

/home/ddahl/code/moz/mozilla-central/mozilla/netwerk/base/src/nsIOService.cpp:199: error: expected primary-expression before ‘)’ token

make[6]: *** [nsIOService.o] Error 1
make[5]: *** [libs] Error 2
make[4]: *** [libs] Error 2
make[3]: *** [libs_tier_necko] Error 2
make[2]: *** [tier_necko] Error 2
make[1]: *** [default] Error 2
make: *** [build] Error 2


Here is the offending line of code:

NS_FUNCTION_TIMER_INIT("nsIOService::Init");


Here is the macro:

#define NS_FUNCTION_TIMER_INIT(description, ...) nsFunctionTimer ft(description, __VA_ARGS__)
Oh forgot to mention does it matter that nsFunctionTimer has an overloaded constructor?
That won't work -- if you have varargs in a macro you have to actually use the args.  Something that might work is:

NS_FUNCTION_TIMER_INIT(...)  nsFunctionTimer (__VA_ARGS__)

also, you can't call these objects "ft".  Use something like ft__autogen or similar.  I also wouldn't call the macro _INIT; _DECLARE is too wordy, so maybe just omit it and call it NS_FUNCTION_TIMER(...).

But, again, like I mentioned, a convenience helper like NS_TIME_FUNCTION is what you want here -- you can get the function name from __FUNCTION__ already, so the common usage would be something like:

NS_TIME_FUNCTION;

which would expand out into  nsFunctionTimer ft__autogen("%s", __FUNCTION__)

or similar.
Attached patch WIP - does not build (obsolete) — Splinter Review
So when using the convenience helper would the macro be defined like so:

#define NS_TIME_FUNCTION(...) nsFunctionTimer ft__autogen("%s", __FUNCTION__)(__VA_ARGS__) 

// and:

#define NS_TIME_FUNCTION_MARK(...) ft__autogen("%s", __FUNCTION__).Mark(__VA_ARGS__)

Or something like that? do the "__" in ft__autogen act like a placeholder for the __FUNCTION__ name?

Sorry for the dumb question. In python I would do something like 

macro_name = "ft_%s" % __name__

to do string replacement of the function name into the macro_name string
Nope, not quite.  There are two separate things.  One is a straightforward "time this function" shorthand.  This would be:

#define NS_TIME_FUNCTION   nsFunctionTimer ft__autogen("%s", __FUNCTION__)
#define NS_TIME_FUNCTION_MARK(...)   ft_autogen.Mark(__VA_ARGS__)

the __ in "ft__autogen" has no meaning, it's just there as a variable name that someone is highly unlikely to use in their own code.  __FUNCTION__ is special in the preprocessor, and expands out to a string containing the current function name (like __VA_ARGS__ expands out to the contents of "...").

Usage would be something like:

void Foo() {
  NS_TIME_FUNCTION;
  ...
  NS_TIME_FUNCTION_MARK("Some Step");
}

which expands out to:

void Foo() {
  nsFunctionTimer ft__autogen("%s", "Foo");
  ...
  ft__autogen.Mark("Some Step");
}

You would also want:

#define NS_TIME_FUNCTION_MIN(_ms)  nsFunctionTimer ft__autogen((_ms), "%s", __FUNCTION__)

to allow a minimum time in ms to be specified for any output.

Those are the convenience functions that would be used in most cases.  But you'd also want:

#define NS_TIME_FUNCTION_FMT(...)  nsFunctionTimer ft__autogen(__VA_ARGS__)
#define NS_TIME_FUNCTION_MIN_FMT(_ms, ...)  nsFunctionTimer ft__autogen((_ms), __VA_ARGS__)

to allow someone to use their own format string for the display instead of just using the function name.

Any other usage, e.g. using a custom object name, should just be handled by direct calls to nsFunctionTimer I guess, with some appropriate #ifdef NS_FUNCTION_TIMING around it... but I can't imagine where that would appear, though perhaps in an inner block or something?
(In reply to comment #7)
> vlad:  Can we gut the old stuff, then?

Yeah, we probably should.. looking at http://mxr.mozilla.org/mozilla-central/search?string=timeline is pretty funny.  Some timing of startup, and some intricate timing of nsCharsetMenu and nsPlatformCharset, as well as some timing of pyxpcom... and that's it.

Though hmm... we should probably convert this to use nspr logging instead of just straight printfs before checking in as well.  The logging stuff isn't too high overhead, right?
Scoping issues on this try. I *think* the nsFunctionTimer class is in ok shape. The following error points to the scope of the MACRO.


nsCategoryManager.cpp
In file included from /home/ddahl/code/moz/mozilla-central/mozilla/xpcom/components/nsCategoryManager.cpp:64:
../../dist/include/nsFunctionTimer.h:118:31: warning: anonymous variadic macros were introduced in C99
../../dist/include/nsFunctionTimer.h:120:30: warning: anonymous variadic macros were introduced in C99
../../dist/include/nsFunctionTimer.h:122:39: warning: anonymous variadic macros were introduced in C99
/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/components/nsCategoryManager.cpp: In function ‘nsresult NS_CreateServicesFromCategory(const char*, nsISupports*, const char*)’:
/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/components/nsCategoryManager.cpp:910: error: ‘ft_autogen’ was not declared in this scope
make[5]: *** [nsCategoryManager.o] Error 1
make[4]: *** [libs] Error 2
make[3]: *** [libs_tier_xpcom] Error 2
make[2]: *** [tier_xpcom] Error 2
make[1]: *** [default] Error 2
make: *** [build] Error 2
Attachment #387688 - Attachment is obsolete: true
Attachment #388373 - Attachment is obsolete: true
Attachment #388577 - Flags: review?
Attachment #387688 - Flags: review?(vladimir)
Attachment #388577 - Flags: review? → review?(vladimir)
Attached patch PR_LOG conversion take 2 (obsolete) — Splinter Review
Not quite sure how to declare the PR_LOG module. Followed examples in mxr, to no avail.

nsObserverList.cpp
In file included from /home/ddahl/code/moz/mozilla-central/mozilla/xpcom/ds/nsObserverList.cpp:45:
../../dist/include/nsFunctionTimer.h:115:31: warning: anonymous variadic macros were introduced in C99
../../dist/include/nsFunctionTimer.h:117:30: warning: anonymous variadic macros were introduced in C99
../../dist/include/nsFunctionTimer.h:119:39: warning: anonymous variadic macros were introduced in C99
In file included from /home/ddahl/code/moz/mozilla-central/mozilla/xpcom/ds/nsObserverList.cpp:45:
../../dist/include/nsFunctionTimer.h:19: error: ‘PRLogModuleInfo* PR_NewLogModule(const char*)’ cannot appear in a constant-expression
../../dist/include/nsFunctionTimer.h:19: error: a function call cannot appear in a constant-expression
../../dist/include/nsFunctionTimer.h:19: error: invalid in-class initialization of static data member of non-integral type ‘PRLogModuleInfo*’
../../dist/include/nsFunctionTimer.h: In constructor ‘nsFunctionTimer::nsFunctionTimer(const char*, ...)’:
../../dist/include/nsFunctionTimer.h:55: error: ‘funcTimerLogModule’ was not declared in this scope
../../dist/include/nsFunctionTimer.h: In member function ‘void nsFunctionTimer::Mark(const char*, ...)’:
../../dist/include/nsFunctionTimer.h:78: error: ‘funcTimerLogModule’ was not declared in this scope
../../dist/include/nsFunctionTimer.h: In destructor ‘nsFunctionTimer::~nsFunctionTimer()’:
../../dist/include/nsFunctionTimer.h:96: error: ‘funcTimerLogModule’ was not declared in this scope
make[5]: *** [nsObserverList.o] Error 1
make[4]: *** [libs] Error 2
make[3]: *** [libs_tier_xpcom] Error 2
make[2]: *** [tier_xpcom] Error 2
make[1]: *** [default] Error 2
make: *** [build] Error 2
Attachment #388577 - Attachment is obsolete: true
Attachment #388607 - Flags: review?(vladimir)
Attachment #388577 - Flags: review?(vladimir)
Comment on attachment 388607 [details] [diff] [review]
PR_LOG conversion take 2

For future patches, can you split out nsFunctionTimer.{h,cpp} from the actual instrumentation?  Would make it easier to review, and I think the instrumentation will need separate review.  Ideally we'd also figure out how to put the impl of this one and the js one in the same spot, but don't worry about that for now.

>--- /dev/null
>+++ b/xpcom/glue/nsFunctionTimer.h
>@@ -0,0 +1,132 @@
>+#ifndef _NSFUNCTIONTIMER_H_
>+#define _NSFUNCTIONTIMER_H_
>+
>+#define FORCE_PR_LOG
>+#include <prlog.h>
>+
>+#include "prtime.h"
>+
>+#if defined(WINCE)
>+#include <windows.h>
>+#else
>+#include <stdio.h>
>+#endif
>+
>+#include <stdarg.h>
>+
>+class nsFunctionTimer {
>+public:
>+  static PRLogModuleInfo* funcTimerLogModule;

this is right, though style nit... put a s in front of static members, that is sFuncTimerLogModule.

>+  funcTimerLogModule = PR_NewLogModule("nsFuncTimer");

That won't work :)

You need to create nsFunctionTimer.cpp, include the .h, and then do:

PRLogModuleInfo *nsFunctionTimer::funcTimerLogModule = PR_NewLogModule("functimer");


>+#ifdef WINCE
>+    PR_LOG(funcTimerLogModule, PR_LOG_NOTICE, (L"> %S", mString));
>+    // RETAILMSG(1, (L"> %S\r\n", mString));
>+#else
>+    // fprintf(stderr, "> %s\r\n", mString);
>+    PR_LOG(funcTimerLogModule, PR_LOG_NOTICE, ("> %s", mString));
>+#endif

Get rid of the WINCE ifdefs -- no need for them.  wide strings (L"...") were used with RETAILMSG because that's what it expects, but PR_LOG always expects normal 8-bit strings.
Attached patch WIP - linking fails (obsolete) — Splinter Review
sdwilsh gave me a hand trying to set up the sFuncTimerLogModule via a Logging Callback function with PR_CallOnce. Linking dies anyway, which was doing this when I created nsFunctionTimer.cpp. sdwilsh's method does not need the .cpp file, or so he thinks:)

../../toolkit/xre/libxulapp_s.a(nsAppRunner.o): In function `nsFunctionTimer::~nsFunctionTimer()':
nsAppRunner.cpp:(.text._ZN15nsFunctionTimerD1Ev[nsFunctionTimer::~nsFunctionTimer()]+0x61): undefined reference to `nsFunctionTimer::sFuncTimerLogModule'
/usr/bin/ld: ../../toolkit/xre/libxulapp_s.a(nsAppRunner.o): relocation R_386_GOTOFF against undefined hidden symbol `nsFunctionTimer::sFuncTimerLogModule' can not be used when making a shared object
/usr/bin/ld: final link failed: Bad value
collect2: ld returned 1 exit status
make[4]: *** [libxul.so] Error 1
make[3]: *** [libs_tier_toolkit] Error 2
make[2]: *** [tier_toolkit] Error 2
make[1]: *** [default] Error 2
make: *** [build] Error 2
Attachment #388607 - Attachment is obsolete: true
Attachment #388747 - Flags: review?(vladimir)
Attachment #388607 - Flags: review?(vladimir)
Yes, he's wrong, don't do that :)  Just make a cpp file....
Searching for "NS_EXPORT" in mxr only revealed a single instance of using it to export an entire class. 

I tried it like this:

class NS_EXPORT nsFunctionTimer {
...
}

I still have scoping issues though.

One error (i cannot find it in my scrollback) was to the effect that I did not declare arguments for the class - as if it were a function.

Here is the latest error:

/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/glue/nsStringAPI.cpp: In member function ‘PRInt32 nsAString::RFind(const nsAString&, PRInt32, PRInt32 (*)(const PRUnichar*, const PRUnichar*, PRUint32)) const’:
/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/glue/nsStringAPI.cpp:419: warning: comparison between signed and unsigned integer expressions
/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/glue/nsStringAPI.cpp: In member function ‘PRInt32 nsAString::RFind(const char*, PRInt32, PRBool) const’:
/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/glue/nsStringAPI.cpp:444: warning: comparison between signed and unsigned integer expressions
/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/glue/nsStringAPI.cpp: In member function ‘PRInt32 nsACString::RFind(const nsACString&, PRInt32, PRInt32 (*)(const char*, const char*, PRUint32)) const’:
/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/glue/nsStringAPI.cpp:828: warning: comparison between signed and unsigned integer expressions
/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/glue/nsStringAPI.cpp: In member function ‘PRInt32 nsACString::RFind(const char*, PRInt32, PRInt32 (*)(const char*, const char*, PRUint32)) const’:
/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/glue/nsStringAPI.cpp:857: warning: comparison between signed and unsigned integer expressions
nsFunctionTimer.cpp

/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/glue/nsFunctionTimer.cpp:41: error: expected initializer before ‘*’ token
/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/glue/nsFunctionTimer.cpp: In static member function ‘static PRLogModuleInfo* nsFunctionTimer::GetFuncTimerLogModule()’:
/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/glue/nsFunctionTimer.cpp:46: error: ‘sFuncTimerLogModule’ was not declared in this scope
make[5]: *** [nsFunctionTimer.o] Error 1
make[4]: *** [libs] Error 2
make[3]: *** [libs_tier_xpcom] Error 2
make[2]: *** [tier_xpcom] Error 2
make[1]: *** [default] Error 2
make: *** [build] Error 2
Attachment #388928 - Flags: review?(vladimir)
Attachment #388928 - Attachment is patch: true
Attachment #388928 - Attachment mime type: application/octet-stream → text/plain
Attached patch WIP - libxul build issue (obsolete) — Splinter Review
c++  -fno-rtti -fno-exceptions -Wall -Wpointer-arith -Woverloaded-virtual -Wsynth -Wno-ctor-dtor-privacy -Wno-non-virtual-dtor -Wcast-align -Wno-invalid-offsetof -Wno-long-long -pedantic -fno-strict-aliasing -fshort-wchar -pthread -pipe  -DNDEBUG -DTRIMMED -Os -freorder-blocks -fno-reorder-functions  -fPIC -shared -Wl,-z,defs -Wl,-h,libxul.so -o libxul.so  nsStaticXULComponents.o nsUnicharUtils.o nsCompressedCharMap.o nsBidiUtils.o nsRDFResource.o     -lpthread   -Wl,-rpath-link,/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/dist/bin -Wl,-rpath-link,/usr/local/lib  -Wl,--whole-archive ../../embedding/browser/gtk/src/libgtkembedmoz.a ../../toolkit/xre/libxulapp_s.a  ../../staticlib/components/libxpconnect.a ../../staticlib/components/libnecko.a ../../staticlib/components/libuconv.a ../../staticlib/components/libi18n.a ../../staticlib/components/libchardet.a ../../staticlib/components/libjar50.a ../../staticlib/components/libpref.a ../../staticlib/components/libcaps.a ../../staticlib/components/libhtmlpars.a ../../staticlib/components/libimglib2.a ../../staticlib/components/libgklayout.a ../../staticlib/components/libdocshell.a ../../staticlib/components/libembedcomponents.a ../../staticlib/components/libwebbrwsr.a ../../staticlib/components/libnsappshell.a ../../staticlib/components/libtxmgr.a ../../staticlib/components/libchrome.a ../../staticlib/components/libcommandlines.a ../../staticlib/components/libtoolkitcomps.a ../../staticlib/components/libpipboot.a ../../staticlib/components/libpipnss.a ../../staticlib/components/libgkplugin.a ../../staticlib/components/libmozfind.a ../../staticlib/components/libappcomps.a ../../staticlib/components/libunixproxy.a ../../staticlib/components/libxpinstall.a ../../staticlib/components/libjsd.a ../../staticlib/components/libautoconfig.a ../../staticlib/components/libauth.a ../../staticlib/components/libcookie.a ../../staticlib/components/libpermissions.a ../../staticlib/components/libuniversalchardet.a ../../staticlib/components/libcomposer.a ../../staticlib/components/librdf.a ../../staticlib/components/libwindowds.a ../../staticlib/components/libintlapp.a ../../staticlib/components/libfileview.a ../../staticlib/components/libstoragecomps.a ../../staticlib/components/libplaces.a ../../staticlib/components/libtkautocomplete.a ../../staticlib/components/libsatchel.a ../../staticlib/components/libpippki.a ../../staticlib/components/libucvmath.a ../../staticlib/components/libwidget_gtk2.a ../../staticlib/components/libsystem-pref.a ../../staticlib/components/libgkgfxthebes.a ../../staticlib/components/libaccessibility.a ../../staticlib/components/libremoteservice.a ../../staticlib/components/libspellchecker.a ../../staticlib/components/libzipwriter.a ../../staticlib/libxpcom_core.a ../../staticlib/libucvutil_s.a ../../staticlib/libgkgfx.a ../../staticlib/libgfxshared_s.a ../../staticlib/libmozreg_s.a ../../staticlib/libmorkreader_s.a ../../staticlib/libgtkxtbin.a ../../staticlib/libgfxpsshar.a ../../staticlib/libthebes.a  -Wl,--no-whole-archive -L../../dist/lib -lsqlite3 -L../../dist/bin -L../../dist/lib  -L../../dist/bin -L../../dist/lib -L../../jpeg -lmozjpeg -L../../modules/libimg/png -lmozpng ../../gfx/qcms/libmozqcms.a -L/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/dist/bin -lmozjs -L../../dist/bin -L../../dist/lib -lcrmf -lsmime3 -lssl3 -lnss3 -lnssutil3 -lsoftokn3 ../../gfx/cairo/cairo/src/libmozcairo.a ../../gfx/cairo/libpixman/src/libmozlibpixman.a   -lXrender -lfreetype -lfontconfig  -L../../modules/zlib/src -lmozz -L/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/dist/lib -lplds4 -lplc4 -lnspr4 -lpthread -ldl -L//lib -ldbus-glib-1 -ldbus-1 -lgobject-2.0 -lglib-2.0    -lX11  -lXext  -lpangoft2-1.0 -lpango-1.0 -lfreetype -lfontconfig -lgobject-2.0 -lgmodule-2.0 -lglib-2.0   -lgtk-x11-2.0 -latk-1.0 -lpangoft2-1.0 -lfreetype -lfontconfig -lgdk-x11-2.0 -lgdk_pixbuf-2.0 -lm -lpangocairo-1.0 -lgio-2.0 -lpango-1.0 -lcairo -lgobject-2.0 -lgmodule-2.0 -lglib-2.0   -lXt -lgthread-2.0 -lfreetype -lz  -lasound -ldl -lm     
../../toolkit/xre/libxulapp_s.a(nsAppRunner.o): In function `nsFunctionTimer::~nsFunctionTimer()':
nsAppRunner.cpp:(.text._ZN15nsFunctionTimerD1Ev[nsFunctionTimer::~nsFunctionTimer()]+0x60): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
../../toolkit/xre/libxulapp_s.a(nsAppRunner.o): In function `nsFunctionTimer::nsFunctionTimer(char const*, ...)':
nsAppRunner.cpp:(.text._ZN15nsFunctionTimerC1EPKcz[nsFunctionTimer::nsFunctionTimer(char const*, ...)]+0x50): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
../../toolkit/xre/libxulapp_s.a(nsAppRunner.o): In function `nsFunctionTimer::Mark(char const*, ...)':
nsAppRunner.cpp:(.text._ZN15nsFunctionTimer4MarkEPKcz[nsFunctionTimer::Mark(char const*, ...)]+0xbb): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
../../staticlib/components/libnecko.a(nsSocketTransportService2.o): In function `nsSocketTransportService::Init()':
nsSocketTransportService2.cpp:(.text+0x90e): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
../../staticlib/components/libembedcomponents.a(nsAppStartupNotifier.o): In function `nsAppStartupNotifier::Observe(nsISupports*, char const*, unsigned short const*)':
nsAppStartupNotifier.cpp:(.text+0x548): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
../../staticlib/components/libtoolkitcomps.a(nsAppStartup.o):nsAppStartup.cpp:(.text+0xb49): more undefined references to `nsFunctionTimer::GetFuncTimerLogModule()' follow
collect2: ld returned 1 exit status
make[1]: *** [libxul.so] Error 1
make[1]: Leaving directory `/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/toolkit/library'
make: *** [default] Error 2
make: Leaving directory `/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/toolkit/library'
Attachment #388747 - Attachment is obsolete: true
Attachment #388928 - Attachment is obsolete: true
Attachment #389046 - Flags: review?(vladimir)
Attachment #388747 - Flags: review?(vladimir)
Attachment #388928 - Flags: review?(vladimir)
Attached patch WIP - Cpp Patch (obsolete) — Splinter Review
saving my work - splitting up the patch into 3: CPP, JS and Instrumentation
Attachment #389046 - Attachment is obsolete: true
Attachment #389046 - Flags: review?(vladimir)
Attached patch WIP - JS patch (obsolete) — Splinter Review
Attached patch WIP - Instrumentation patch (obsolete) — Splinter Review
Tried a few different approaches to get NS_EXPORT to make the functionTimer global. I tried going back and forth with the PRLogModuleInfo method inside the header file and then inside the cpp file. No dice, I still get this linking error:

c++  -fno-rtti -fno-exceptions -Wall -Wpointer-arith -Woverloaded-virtual -Wsynth -Wno-ctor-dtor-privacy -Wno-non-virtual-dtor -Wcast-align -Wno-invalid-offsetof -Wno-long-long -pedantic -fno-strict-aliasing -fshort-wchar -pthread -pipe  -DNDEBUG -DTRIMMED -Os -freorder-blocks -fno-reorder-functions  -fPIC -shared -Wl,-z,defs -Wl,-h,libxul.so -o libxul.so  nsStaticXULComponents.o nsUnicharUtils.o nsCompressedCharMap.o nsBidiUtils.o nsRDFResource.o     -lpthread   -Wl,-rpath-link,/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/dist/bin -Wl,-rpath-link,/usr/local/lib  -Wl,--whole-archive ../../embedding/browser/gtk/src/libgtkembedmoz.a ../../toolkit/xre/libxulapp_s.a  ../../staticlib/components/libxpconnect.a ../../staticlib/components/libnecko.a ../../staticlib/components/libuconv.a ../../staticlib/components/libi18n.a ../../staticlib/components/libchardet.a ../../staticlib/components/libjar50.a ../../staticlib/components/libpref.a ../../staticlib/components/libcaps.a ../../staticlib/components/libhtmlpars.a ../../staticlib/components/libimglib2.a ../../staticlib/components/libgklayout.a ../../staticlib/components/libdocshell.a ../../staticlib/components/libembedcomponents.a ../../staticlib/components/libwebbrwsr.a ../../staticlib/components/libnsappshell.a ../../staticlib/components/libtxmgr.a ../../staticlib/components/libchrome.a ../../staticlib/components/libcommandlines.a ../../staticlib/components/libtoolkitcomps.a ../../staticlib/components/libpipboot.a ../../staticlib/components/libpipnss.a ../../staticlib/components/libgkplugin.a ../../staticlib/components/libmozfind.a ../../staticlib/components/libappcomps.a ../../staticlib/components/libunixproxy.a ../../staticlib/components/libxpinstall.a ../../staticlib/components/libjsd.a ../../staticlib/components/libautoconfig.a ../../staticlib/components/libauth.a ../../staticlib/components/libcookie.a ../../staticlib/components/libpermissions.a ../../staticlib/components/libuniversalchardet.a ../../staticlib/components/libcomposer.a ../../staticlib/components/librdf.a ../../staticlib/components/libwindowds.a ../../staticlib/components/libintlapp.a ../../staticlib/components/libfileview.a ../../staticlib/components/libstoragecomps.a ../../staticlib/components/libplaces.a ../../staticlib/components/libtkautocomplete.a ../../staticlib/components/libsatchel.a ../../staticlib/components/libpippki.a ../../staticlib/components/libucvmath.a ../../staticlib/components/libwidget_gtk2.a ../../staticlib/components/libsystem-pref.a ../../staticlib/components/libgkgfxthebes.a ../../staticlib/components/libaccessibility.a ../../staticlib/components/libremoteservice.a ../../staticlib/components/libspellchecker.a ../../staticlib/components/libzipwriter.a ../../staticlib/libxpcom_core.a ../../staticlib/libucvutil_s.a ../../staticlib/libgkgfx.a ../../staticlib/libgfxshared_s.a ../../staticlib/libmozreg_s.a ../../staticlib/libmorkreader_s.a ../../staticlib/libgtkxtbin.a ../../staticlib/libgfxpsshar.a ../../staticlib/libthebes.a  -Wl,--no-whole-archive -L../../dist/lib -lsqlite3 -L../../dist/bin -L../../dist/lib  -L../../dist/bin -L../../dist/lib -L../../jpeg -lmozjpeg -L../../modules/libimg/png -lmozpng ../../gfx/qcms/libmozqcms.a -L/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/dist/bin -lmozjs -L../../dist/bin -L../../dist/lib -lcrmf -lsmime3 -lssl3 -lnss3 -lnssutil3 -lsoftokn3 ../../gfx/cairo/cairo/src/libmozcairo.a ../../gfx/cairo/libpixman/src/libmozlibpixman.a   -lXrender -lfreetype -lfontconfig  -L../../modules/zlib/src -lmozz -L/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/dist/lib -lplds4 -lplc4 -lnspr4 -lpthread -ldl -L//lib -ldbus-glib-1 -ldbus-1 -lgobject-2.0 -lglib-2.0    -lX11  -lXext  -lpangoft2-1.0 -lpango-1.0 -lfreetype -lfontconfig -lgobject-2.0 -lgmodule-2.0 -lglib-2.0   -lgtk-x11-2.0 -latk-1.0 -lpangoft2-1.0 -lfreetype -lfontconfig -lgdk-x11-2.0 -lgdk_pixbuf-2.0 -lm -lpangocairo-1.0 -lgio-2.0 -lpango-1.0 -lcairo -lgobject-2.0 -lgmodule-2.0 -lglib-2.0   -lXt -lgthread-2.0 -lfreetype -lz  -lasound -ldl -lm     
../../toolkit/xre/libxulapp_s.a(nsAppRunner.o): In function `ScopedXPCOMStartup::SetWindowCreator(nsINativeAppSupport*)':
nsAppRunner.cpp:(.text+0x136f): undefined reference to `nsFunctionTimer::sFuncTimerLogModule'
../../toolkit/xre/libxulapp_s.a(nsAppRunner.o): In function `nsFunctionTimer::nsFunctionTimer(char const*, ...)':
nsAppRunner.cpp:(.text._ZN15nsFunctionTimerC1EPKcz[nsFunctionTimer::nsFunctionTimer(char const*, ...)]+0x59): undefined reference to `nsFunctionTimer::sFuncTimerLogModule'
nsAppRunner.cpp:(.text._ZN15nsFunctionTimerC1EPKcz[nsFunctionTimer::nsFunctionTimer(char const*, ...)]+0x94): undefined reference to `nsFunctionTimer::sFuncTimerLogModule'
../../staticlib/components/libnecko.a(nsSocketTransportService2.o): In function `nsSocketTransportService::Init()':
nsSocketTransportService2.cpp:(.text+0x90e): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
../../staticlib/components/libembedcomponents.a(nsAppStartupNotifier.o): In function `nsAppStartupNotifier::Observe(nsISupports*, char const*, unsigned short const*)':
nsAppStartupNotifier.cpp:(.text+0x548): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
../../staticlib/components/libnsappshell.a(nsAppShellService.o): In function `nsFunctionTimer::~nsFunctionTimer()':
nsAppShellService.cpp:(.text._ZN15nsFunctionTimerD1Ev[nsFunctionTimer::~nsFunctionTimer()]+0x60): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
../../staticlib/components/libtoolkitcomps.a(nsAppStartup.o): In function `nsAppStartup::Init()':
nsAppStartup.cpp:(.text+0xb49): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
collect2: ld returned 1 exit status
make[1]: *** [libxul.so] Error 1
make[1]: Leaving directory `/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/toolkit/library'
make: *** [default] Error 2
make: Leaving directory `/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/toolkit/library'
Adding a tiny patch that calls NS_TIME_FUNCTION once and NS_TIME_FUNCTION_MARK once. You should be able to build the Cpp patch without any instrumentation patches, once you add this one you cannot link with libxul.
Attachment #389562 - Flags: review?(vladimir)
Attached patch updated patch (obsolete) — Splinter Review
Ok, here's an updated patch that I think is good to go.. fixes some minor things in the previous patches:

1) needed NS_COM to get the proper exports from xpcom;

2) Can't use the PR_LOG macros and FORCE_PR_LOGGING in an include file; we have to make the PRLog function calls directly;

3) Duplicates the code between js and xpcom -- there wasn't a good way to get around this;

4) Moved xpcom piece to xpcom/base (not glue).

Requesting review from brendan on the JS piece, and bsmedberg on the xpcom piece.  (It doesn't really have much to do with xpcom, we just have no good place to put things like this!)
Attachment #389060 - Attachment is obsolete: true
Attachment #389562 - Attachment is obsolete: true
Attachment #389576 - Flags: review?(brendan)
Attachment #389562 - Flags: review?(vladimir)
i cleared my queue, applied this patch, and still have linking issues, different linking problems anyway:

c++  -fno-rtti -fno-exceptions -Wall -Wpointer-arith -Woverloaded-virtual -Wsynth -Wno-ctor-dtor-privacy -Wno-non-virtual-dtor -Wcast-align -Wno-invalid-offsetof -Wno-long-long -pedantic -fno-strict-aliasing -fshort-wchar -pthread -pipe  -DNDEBUG -DTRIMMED -Os -freorder-blocks -fno-reorder-functions  -fPIC -shared -Wl,-z,defs -Wl,-h,libxul.so -o libxul.so  nsStaticXULComponents.o nsUnicharUtils.o nsCompressedCharMap.o nsBidiUtils.o nsRDFResource.o     -lpthread   -Wl,-rpath-link,/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/dist/bin -Wl,-rpath-link,/usr/local/lib  -Wl,--whole-archive ../../embedding/browser/gtk/src/libgtkembedmoz.a ../../toolkit/xre/libxulapp_s.a  ../../staticlib/components/libxpconnect.a ../../staticlib/components/libnecko.a ../../staticlib/components/libuconv.a ../../staticlib/components/libi18n.a ../../staticlib/components/libchardet.a ../../staticlib/components/libjar50.a ../../staticlib/components/libpref.a ../../staticlib/components/libcaps.a ../../staticlib/components/libhtmlpars.a ../../staticlib/components/libimglib2.a ../../staticlib/components/libgklayout.a ../../staticlib/components/libdocshell.a ../../staticlib/components/libembedcomponents.a ../../staticlib/components/libwebbrwsr.a ../../staticlib/components/libnsappshell.a ../../staticlib/components/libtxmgr.a ../../staticlib/components/libchrome.a ../../staticlib/components/libcommandlines.a ../../staticlib/components/libtoolkitcomps.a ../../staticlib/components/libpipboot.a ../../staticlib/components/libpipnss.a ../../staticlib/components/libgkplugin.a ../../staticlib/components/libmozfind.a ../../staticlib/components/libappcomps.a ../../staticlib/components/libunixproxy.a ../../staticlib/components/libxpinstall.a ../../staticlib/components/libjsd.a ../../staticlib/components/libautoconfig.a ../../staticlib/components/libauth.a ../../staticlib/components/libcookie.a ../../staticlib/components/libpermissions.a ../../staticlib/components/libuniversalchardet.a ../../staticlib/components/libcomposer.a ../../staticlib/components/librdf.a ../../staticlib/components/libwindowds.a ../../staticlib/components/libintlapp.a ../../staticlib/components/libfileview.a ../../staticlib/components/libstoragecomps.a ../../staticlib/components/libplaces.a ../../staticlib/components/libtkautocomplete.a ../../staticlib/components/libsatchel.a ../../staticlib/components/libpippki.a ../../staticlib/components/libucvmath.a ../../staticlib/components/libwidget_gtk2.a ../../staticlib/components/libsystem-pref.a ../../staticlib/components/libgkgfxthebes.a ../../staticlib/components/libaccessibility.a ../../staticlib/components/libremoteservice.a ../../staticlib/components/libspellchecker.a ../../staticlib/components/libzipwriter.a ../../staticlib/libxpcom_core.a ../../staticlib/libucvutil_s.a ../../staticlib/libgkgfx.a ../../staticlib/libgfxshared_s.a ../../staticlib/libmozreg_s.a ../../staticlib/libmorkreader_s.a ../../staticlib/libgtkxtbin.a ../../staticlib/libgfxpsshar.a ../../staticlib/libthebes.a  -Wl,--no-whole-archive -L../../dist/lib -lsqlite3 -L../../dist/bin -L../../dist/lib  -L../../dist/bin -L../../dist/lib -L../../jpeg -lmozjpeg -L../../modules/libimg/png -lmozpng ../../gfx/qcms/libmozqcms.a -L/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/dist/bin -lmozjs -L../../dist/bin -L../../dist/lib -lcrmf -lsmime3 -lssl3 -lnss3 -lnssutil3 -lsoftokn3 ../../gfx/cairo/cairo/src/libmozcairo.a ../../gfx/cairo/libpixman/src/libmozlibpixman.a   -lXrender -lfreetype -lfontconfig  -L../../modules/zlib/src -lmozz -L/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/dist/lib -lplds4 -lplc4 -lnspr4 -lpthread -ldl -L//lib -ldbus-glib-1 -ldbus-1 -lgobject-2.0 -lglib-2.0    -lX11  -lXext  -lpangoft2-1.0 -lpango-1.0 -lfreetype -lfontconfig -lgobject-2.0 -lgmodule-2.0 -lglib-2.0   -lgtk-x11-2.0 -latk-1.0 -lpangoft2-1.0 -lfreetype -lfontconfig -lgdk-x11-2.0 -lgdk_pixbuf-2.0 -lm -lpangocairo-1.0 -lgio-2.0 -lpango-1.0 -lcairo -lgobject-2.0 -lgmodule-2.0 -lglib-2.0   -lXt -lgthread-2.0 -lfreetype -lz  -lasound -ldl -lm     
../../staticlib/components/libnecko.a(nsSocketTransportService2.o): In function `nsSocketTransportService::Init()':
nsSocketTransportService2.cpp:(.text+0x90e): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
../../staticlib/components/libgklayout.a(nsPageFrame.o): In function `nsPageFrame::DrawHeaderFooter(nsIRenderingContext&, nsPageFrame::nsHeaderFooterEnum, int, nsString const&, nsRect const&, int, int, int)':
nsPageFrame.cpp:(.text+0xbec): undefined reference to `HasRTLChars(nsAString_internal&)'
../../staticlib/components/libgklayout.a(nsTextBoxFrame.o): In function `nsTextBoxFrame::CalculateTitleForWidth(nsPresContext*, nsIRenderingContext&, int)':
nsTextBoxFrame.cpp:(.text+0x42b): undefined reference to `HasRTLChars(nsAString_internal&)'
../../staticlib/components/libembedcomponents.a(nsAppStartupNotifier.o): In function `nsAppStartupNotifier::Observe(nsISupports*, char const*, unsigned short const*)':
nsAppStartupNotifier.cpp:(.text+0x548): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
../../staticlib/components/libnsappshell.a(nsAppShellService.o): In function `nsFunctionTimer::~nsFunctionTimer()':
nsAppShellService.cpp:(.text._ZN15nsFunctionTimerD1Ev[nsFunctionTimer::~nsFunctionTimer()]+0x60): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
../../staticlib/components/libtoolkitcomps.a(nsAppStartup.o): In function `nsAppStartup::Init()':
nsAppStartup.cpp:(.text+0xb49): undefined reference to `nsFunctionTimer::GetFuncTimerLogModule()'
/usr/bin/ld: libxul.so: hidden symbol `HasRTLChars(nsAString_internal&)' isn't defined
/usr/bin/ld: final link failed: Nonrepresentable section on output
collect2: ld returned 1 exit status
make[1]: *** [libxul.so] Error 1
make[1]: Leaving directory `/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/toolkit/library'
make: *** [default] Error 2
make: Leaving directory `/home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/toolkit/library'


The weird thing is that a total rebuild appears to work, no errors, but when you run the browser you get: 

ddahl-t500 ~/code/moz/mozilla-central/mozilla % ../obj-i686-pc-linux-gnu-optimize/dist/bin/firefox -P -no-remote
../obj-i686-pc-linux-gnu-optimize/dist/bin/firefox-bin: error while loading shared libraries: libxul.so: cannot open shared object file: No such file or directory


I built toolkit/library to get the previous error.
You need to do a clean build; you're pulling in things that don't have the right dependencies, since the header file changed locations.. and so files aren't getting rebuilt.

If you read the errors, you'll see things like:

nsSocketTransportService2.cpp:(.text+0x90e): undefined reference to
`nsFunctionTimer::GetFuncTimerLogModule()'

nsFunctionTimer::GetFuncTimerLogModule() doesn't exist any more.
Yeah - sorry. Just started a complete rm -fr clobber build.
Getting rid of fprintf calls.
slight tweak to XRE_Main
Attachment #389062 - Attachment is obsolete: true
Attached patch v0.3 - instrumentation - latest (obsolete) — Splinter Review
This is the latest instrumentation patch
Attachment #389061 - Attachment is obsolete: true
Attachment #389812 - Attachment is obsolete: true
Attachment #389814 - Attachment is obsolete: true
Attachment #389576 - Attachment is patch: true
Attachment #389576 - Attachment mime type: application/octet-stream → text/plain
Comment on attachment 389576 [details] [diff] [review]
updated patch

Can you use namespaces for new code? mozilla::FunctionTimer and mozilla::FunctionTimerLog and mozilla/FunctionTimer.h

Also, I'd like to see the macros at the top of functiontimer.h instead of the bottom, since that's primarily what consumers will be using.

Also, needs a file-scope doccomment explaining in general how to use the macros... from reading them, you'd put NS_TIME_FUNCTION at the top of your function?

Is __FUNCTION__ portable or do you not care?
Attachment #389576 - Flags: review?(benjamin) → review-
I just tested __FUNCTION__ on msvc so it seems "portable enough" - as a native code noob, what other compilers should we be concerned with? Do we use gcc everywhere else?
It's portable enough -- if some freaky compiler doesn't handle it, we can add a configure test then and they can get something lamer, or no support for it at all.
__FUNCTION__ is fine; though it's often not good enough, msvc has __PRETTY_FUNCTION__ which is super verbose.  Either way, that's not an issue.

But turns out I can't put nsFunctionTimer.h (or whatever) in xpcom, even if I move it to xpcom glue or something; there are things that don't link with this.  I can do it include-file-only if I can modify NSPR, or I can create a mozilla utility library that gets linked in to everything.  I'm leaning towards the latter.
(er,gcc has PRETTY_FUNCTION, not msvc; msvc has __FUNCSIG__)
What about putting it in JS? Only half :-P.

NSPR still seems the best place.

/be
(In reply to comment #41)

> But turns out I can't put nsFunctionTimer.h (or whatever) in xpcom, even if I
> move it to xpcom glue or something; there are things that don't link with this.
>  I can do it include-file-only if I can modify NSPR, or I can create a mozilla
> utility library that gets linked in to everything.  I'm leaning towards the
> latter.

vlad:

I just got the namespaces implemented int he cpp parts, and am about to update the jsftimer.h and .cpp. As far as moving this into a utility lib, will the code have to change drastically?
it won't, we just have to figure out where to put it; a copy in xpcom and a copy in js isn't good enough (and having two copies sucked to being with, I just couldn't figure out how to do it otherwise).

Putting PR_GetLogModule(name) in nspr would work, which would act as a "get-or-create" operation on the given name, but modifying nspr is even harder.
(In reply to comment #45)
> Putting PR_GetLogModule(name) in nspr would work, which would act as a
> "get-or-create" operation on the given name, but modifying nspr is even harder.

Has wtc heard the pitch yet?

/be
Attached patch 0.1 FunctionTimer Patch (obsolete) — Splinter Review
About done addressing review comments, not sure how to use this patch on the JS side, do we need an xpconnect component that wraps the JS_TIME_FUNCTION macros?

* still need to flesh out the doccomments.
Attachment #389576 - Attachment is obsolete: true
Attachment #390863 - Flags: review?(vladimir)
Attachment #389576 - Flags: review?(brendan)
(In reply to comment #46)
> (In reply to comment #45)
> > Putting PR_GetLogModule(name) in nspr would work, which would act as a
> > "get-or-create" operation on the given name, but modifying nspr is even harder.
> 
> Has wtc heard the pitch yet?

No, I haven't.  Brendan first cc'ed me in comment 43, and
I thought he was talking about the __FUNCTION__ macro.
Attached patch add PR_GetLogModule (obsolete) — Splinter Review
wtc, here's the piece I'd like to add to nspr; unfortunately I can't figure out how to use plhash from prlog.cpp -- what am I missing here?  Might be able to use a simple linked list here as well, as the number of modules is likely to be small, but that'll probably change if/when people start using this mechanism more in the future.

ddahl, I'll attach an updated patch for the actual implementation soon, as soon as we figure out this piece.
Attachment #390863 - Attachment is obsolete: true
Attachment #391687 - Flags: review?(wtc)
Attachment #390863 - Flags: review?(vladimir)
... though the other option is to just move this entirely into nspr, since I see that nspr does have a c++ section.
Comment on attachment 391687 [details] [diff] [review]
add PR_GetLogModule

Vlad, thanks for the patch.  PLHashTable is in the "plds4" library,
which depends on the "nspr4" library, so you can't use PLHashTable
in the "nspr4" library.  You will need to implement the table of
log modules manually, as a linked list or some other data structure.

Another problem with this patch is that it is not thread-safe.  I
guess you're just using it to illustrate what you're trying to do.

The C++ section in NSPR is dead code.  It probably should be CVS
removed.
Attached patch add PR_GetLogModule, v2 (obsolete) — Splinter Review
Maybe something like this?  (I had completely forgotten about thread safety!)  Not great from a lookup perf point of view, but if it becomes a problem we can fix that in some other way.
Attachment #391687 - Attachment is obsolete: true
Attachment #391710 - Flags: review?(wtc)
Attachment #391687 - Flags: review?(wtc)
Attached patch functiontimer code (obsolete) — Splinter Review
This builds on top of PR_GetLogModule; not r?'ing until we figure that piece out.
Comment on attachment 391710 [details] [diff] [review]
add PR_GetLogModule, v2

Vlad, thanks for the patch.  I have some questions and suggested changes
below.

>+** ... Note that only
>+** log modules created by PR_GetLogModule are tracked, not those
>+** created by PR_NewLogModule.

This limitation is surprising.  Why can't PR_GetLogModule track the log
modules created by PR_NewLogModule?

Please document these subtle issues:
- We can't enhance PR_NewLogModule because ... (I guess PR_NewLogModule
  inadvertently allow modules with the same name)
- PR_GetLogModule addresses the following issues in PR_NewLogModule (I
  guess: unique module names, no need to create a log module in some
  "init" function)
- The log modules created by PR_NewLogModule and PR_GetLogModule must
  be tracked separately because ... (I certainly hope we can just use
  a single list of log modules)

>+typedef struct _PRLogModuleInfoLink PRLogModuleInfoLink;
>+struct _PRLogModuleInfoLink {
>+    PRLogModuleInfo *logModule;
>+    PRLogModuleInfoLink *next;
>+};

Why can't you use the PRLogModuleInfo structure, which already has a
'next' member?

>+static PRLogModuleInfoLink *_pr_logModules = NULL;
>+/* initialized in prinit */
>+extern PRLock *_pr_logModulesLock;

The log modules created by PR_NewLogModule are already linked into
a list: logModules.  If you must use a separate linked list for the
log modules created by PR_GetLogModule, please declare it near the
declaration for logModules to stress the fact that they're related.

By the way, I found that PR_NewLogModule adds the newly created log
module to logModules without the protection of a lock.  That is a
bug.  Let's just use your _pr_logModulesLock to protect it.

>+PR_IMPLEMENT(PRLogModuleInfo*) PR_GetLogModule(const char *name)
>+{
>+    PRLogModuleInfo *lm = NULL;
>+    PRLogModuleInfoLink *link = _pr_logModules;
>+
>+    while (link) {
>+        if (strcmp(link->logModule->name, name) == 0)
>+            break;
>+
>+        link = link->next;
>+    }

This while loop, which traverses the linked list, should also be
protected with the lock.
Attachment #391710 - Flags: review?(wtc) → review-
Attached patch add PR_GetLogModule, v3 (obsolete) — Splinter Review
Updated NSPR patch.  Thanks for the comments, wtc -- I didn't even realize that there already was an existing linked list of log modules, somehow missed that while looking through the code.

This could become even simpler if we were to just have NewLogModule return an existing log module if it had the same name.  Given that you can't destroy log modules, does that sound like an acceptable change?  In that case, no new API would be required, and I'm pretty sure behaviour wouldn't change even if someone was creating multiple log modules with the same name before (unless they were manually reaching in to the struct and fiddling bits for their particular instance after it's been initialized).
Attachment #391710 - Attachment is obsolete: true
Attachment #393384 - Flags: review?(wtc)
Fix in previous patch -- since NewLogModule now grabs the PRLock, we need to initialize the PRLock in PR_Init before we call NewLogModule, or bad things happen.  (This leads to weird crashes on startup, since NewLogModule is used in global data...)
Attachment #393384 - Attachment is obsolete: true
Attachment #393839 - Flags: review?(wtc)
Attachment #393384 - Flags: review?(wtc)
Comment on attachment 393839 [details] [diff] [review]
add PR_GetLogModule, v4

r=wtc.  Thanks for the patch.  I will think about whether
we can just change PR_NewLogModule to return an existing
module if a module by that name already exists.  NSPR
has strict backward compatibility requirements, so this
kind of subtle behavior change needs a lot of thought.
Often we just add a new variant of the function to be
safe.

In nsprpub/pr/src/io/prlog.c

> /*
>+ * Lock used to lock the set of modules we have.
>+ * Initialized in prinit.
>+ */

Nit: "Initialized" => "Defined and initialized"
     prinit => prinit.c

I would mention the name of the variable 'logModules' explicitly.

>+PR_IMPLEMENT(PRLogModuleInfo*) PR_GetLogModule(const char *name)
>+{
>+    PRLogModuleInfo *lm;
>+
>+    if (!_pr_initialized) _PR_ImplicitInitialization();
>+
>+    lm = _PR_FindLogModule(name);
>+    if (lm)
>+        return lm;

The fast code path, calling _PR_FindLogModule without holding
a lock, is not thread-safe.  Let's delete it and just rely on
the slow code path in the critical section below.

In nsprpub/pr/src/misc/prinit.c:

>+/* Lock protecting PR_GetLockModules' linked list */

Nit: Lock protecting the logModules linked list in prlog.c

>+    /* Must happen before any PR_NewLogModule calls! */
>+    _pr_logModulesLock = PR_NewLock();
>+    PR_ASSERT(NULL != _pr_logModulesLock);

It would be better to move this code to right above the
first PR_NewLogModule call to make the point clear.

Are you sure we can call PR_NewLock() this early?

Another approach is to allow PR_NewLogModule to be called
with _pr_logModulesLock being NULL, which would indicate
we're inside NSPR initialization.  We do similar things
elsewhere in prlog.c:
http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/nsprpub/pr/src/io/prlog.c&rev=3.50&mark=451-453#440
Attachment #393839 - Flags: review?(wtc) → review+
(In reply to comment #57)
> (From update of attachment 393839 [details] [diff] [review])
> >+PR_IMPLEMENT(PRLogModuleInfo*) PR_GetLogModule(const char *name)
> >+{
> >+    PRLogModuleInfo *lm;
> >+
> >+    if (!_pr_initialized) _PR_ImplicitInitialization();
> >+
> >+    lm = _PR_FindLogModule(name);
> >+    if (lm)
> >+        return lm;
> 
> The fast code path, calling _PR_FindLogModule without holding
> a lock, is not thread-safe.  Let's delete it and just rely on
> the slow code path in the critical section below.

It is -- modules can never be deleted, and new modules are always added to the front of the list.  The module pointer there should always be valid (barring a partial update of the pointer value in memory or something, which I don't think can ever happen... we could use an atomic swap to ensure, I guess, when creating a new module).

I don't want to remove the fast path because that maens that every GetLogModule call will require a mutex lock/unlock, which seems excessive for places where we're using GetLogModule explicitly because there's no convenient place to store a cached pointer to one.

> >+    /* Must happen before any PR_NewLogModule calls! */
> >+    _pr_logModulesLock = PR_NewLock();
> >+    PR_ASSERT(NULL != _pr_logModulesLock);
> 
> It would be better to move this code to right above the
> first PR_NewLogModule call to make the point clear.
> 
> Are you sure we can call PR_NewLock() this early?

No, but I'm not sure whether it can be called at any point in that function -- that is, there's nothing in there that indicates "this is early initialization", just a somewhat haphazard collection of inits.

> Another approach is to allow PR_NewLogModule to be called
> with _pr_logModulesLock being NULL, which would indicate
> we're inside NSPR initialization.  We do similar things
> elsewhere in prlog.c:
> http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/nsprpub/pr/src/io/prlog.c&rev=3.50&mark=451-453#440

that's a good idea; I'll do that.
Vlad, it is risky to make that kind of assumption about what
you can do without holding a lock.  I am not qualified to
review lock-free code.
Attachment #393839 - Flags: review+
Comment on attachment 393839 [details] [diff] [review]
add PR_GetLogModule, v4

The race seems harmless to me. We grab the head pointer of a list that is never mutated. Additions happen at the front by updating the head pointer. As long the update of the head pointer happens after the link was set, this should be always safe.
(In reply to comment #58)
>
> I don't want to remove the fast path because that maens that every GetLogModule
> call will require a mutex lock/unlock, which seems excessive for places where
> we're using GetLogModule explicitly because there's no convenient place to
> store a cached pointer to one.

Vlad, I think PR_CallOnce should work for you:
https://developer.mozilla.org/en/PR_CallOnce

static PRLogModuleInfo *lm_foo;
static PRCallOnceType lm_foo_once;

static PRStatus InitFooLogModule(void)
{
  lm_foo = PR_NewLogModule("foo");
  return PR_SUCCESS;
}

Then, instead of PR_GetLogModule("foo"), you call this function:

PRLogModuleInfo *GetFooLogModule(void)
{
  PR_CallOnce(&lm_foo_once, InitFooLogModule);
  return lm_foo;
}
(In reply to comment #61)
> (In reply to comment #58)
> >
> > I don't want to remove the fast path because that maens that every GetLogModule
> > call will require a mutex lock/unlock, which seems excessive for places where
> > we're using GetLogModule explicitly because there's no convenient place to
> > store a cached pointer to one.
> 
> Vlad, I think PR_CallOnce should work for you:
> https://developer.mozilla.org/en/PR_CallOnce
> 
> static PRLogModuleInfo *lm_foo;
> static PRCallOnceType lm_foo_once;

^ this is the convenient place to store a cached pointer that I don't have -- I have no way to create static data, since the entire implementation lives in a header that gets included by many different components :-)  I can't just export it from xpcom either, since js code ends up using it as well.
Doesn't build do to some more scope fun:

/home/ddahl/code/moz/mozilla-central/mozilla/xpcom/ds/nsObserverList.cpp:149: error: ‘NS_TIME_FUNCTION_MARK’ was not declared in this scope
make[5]: *** [nsObserverList.o] Error 1
make[4]: *** [libs] Error 2
make[3]: *** [libs_tier_xpcom] Error 2
make[2]: *** [tier_xpcom] Error 2
make[1]: *** [default] Error 2
make: *** [build] Error 2
Attachment #390001 - Attachment is obsolete: true
Attachment #395996 - Flags: review?(vladimir)
Comment on attachment 395996 [details] [diff] [review]
v 0.4 instrumentation-patch - unbitrotted

Actually - there are a bunch of #include nsFunctionTimer.h lines that need to be changed to #include FunctionTimer.h
Attachment #395996 - Flags: review?(vladimir)
latest patches a segfaulting, here is my valgrind output:

ddahl-t500 139~/code/moz/mozilla-central/mozilla % valgrind -v ~/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/dist/bin/firefox -P opt-new --no-remote
==24801== Memcheck, a memory error detector.
==24801== Copyright (C) 2002-2007, and GNU GPL'd, by Julian Seward et al.
==24801== Using LibVEX rev 1854, a library for dynamic binary translation.
==24801== Copyright (C) 2004-2007, and GNU GPL'd, by OpenWorks LLP.
==24801== Using valgrind-3.3.1, a dynamic binary instrumentation framework.
==24801== Copyright (C) 2000-2007, and GNU GPL'd, by Julian Seward et al.
==24801== 
--24801-- Command line
--24801--    /home/ddahl/code/moz/mozilla-central/obj-i686-pc-linux-gnu-optimize/dist/bin/firefox
--24801--    -P
--24801--    opt-new
--24801--    --no-remote
--24801-- Startup, with flags:
--24801--    -v
--24801-- Contents of /proc/version:
--24801--   Linux version 2.6.28-15-generic (buildd@palmer) (gcc version 4.3.3 (Ubuntu 4.3.3-5ubuntu4) ) #49-Ubuntu SMP Tue Aug 18 18:40:08 UTC 2009
--24801-- Arch and hwcaps: X86, x86-sse1-sse2
--24801-- Page sizes: currently 4096, max supported 4096
--24801-- Valgrind library directory: /home/ddahl/lib/valgrind
--24801-- Reading syms from /lib/ld-2.9.so (0x4000000)
--24801-- Reading debug info from /lib/ld-2.9.so...
--24801-- ... CRC mismatch (computed 049232cc wanted 022486d8)
--24801--    object doesn't have a symbol table
--24801-- Reading syms from /bin/dash (0x8048000)
--24801--    object doesn't have a symbol table
--24801-- Reading syms from /home/ddahl/lib/valgrind/x86-linux/memcheck (0x38000000)
--24801--    object doesn't have a dynamic symbol table
--24801-- Reading suppressions file: /home/ddahl/lib/valgrind/default.supp
--24801-- Reading syms from /home/ddahl/lib/valgrind/x86-linux/vgpreload_core.so (0x4020000)
==24801== Conditional jump or move depends on uninitialised value(s)
==24801==    at 0x40168CD: (within /lib/ld-2.9.so)
==24801==    by 0x40075B1: (within /lib/ld-2.9.so)
==24801==    by 0x40010C4: (within /lib/ld-2.9.so)
==24801==    by 0x400E035: (within /lib/ld-2.9.so)
==24801==    by 0x4000F7B: (within /lib/ld-2.9.so)
==24801==    by 0x4003551: (within /lib/ld-2.9.so)
==24801==    by 0x40147B0: (within /lib/ld-2.9.so)
==24801==    by 0x4000C1C: (within /lib/ld-2.9.so)
==24801==    by 0x4000816: (within /lib/ld-2.9.so)
==24801== 
==24801== Conditional jump or move depends on uninitialised value(s)
==24801==    at 0x40168DC: (within /lib/ld-2.9.so)
==24801==    by 0x40075B1: (within /lib/ld-2.9.so)
==24801==    by 0x40010C4: (within /lib/ld-2.9.so)
==24801==    by 0x400E035: (within /lib/ld-2.9.so)
==24801==    by 0x4000F7B: (within /lib/ld-2.9.so)
==24801==    by 0x4003551: (within /lib/ld-2.9.so)
==24801==    by 0x40147B0: (within /lib/ld-2.9.so)
==24801==    by 0x4000C1C: (within /lib/ld-2.9.so)
==24801==    by 0x4000816: (within /lib/ld-2.9.so)
==24801== 
==24801== Conditional jump or move depends on uninitialised value(s)
==24801==    at 0x40168EB: (within /lib/ld-2.9.so)
==24801==    by 0x40075B1: (within /lib/ld-2.9.so)
==24801==    by 0x40010C4: (within /lib/ld-2.9.so)
==24801==    by 0x400E035: (within /lib/ld-2.9.so)
==24801==    by 0x4000F7B: (within /lib/ld-2.9.so)
==24801==    by 0x4003551: (within /lib/ld-2.9.so)
==24801==    by 0x40147B0: (within /lib/ld-2.9.so)
==24801==    by 0x4000C1C: (within /lib/ld-2.9.so)
==24801==    by 0x4000816: (within /lib/ld-2.9.so)
==24801== 
==24801== Conditional jump or move depends on uninitialised value(s)
==24801==    at 0x4016A63: (within /lib/ld-2.9.so)
==24801==    by 0x40075B1: (within /lib/ld-2.9.so)
==24801==    by 0x40010C4: (within /lib/ld-2.9.so)
==24801==    by 0x400E035: (within /lib/ld-2.9.so)
==24801==    by 0x4000F7B: (within /lib/ld-2.9.so)
==24801==    by 0x4003551: (within /lib/ld-2.9.so)
==24801==    by 0x40147B0: (within /lib/ld-2.9.so)
==24801==    by 0x4000C1C: (within /lib/ld-2.9.so)
==24801==    by 0x4000816: (within /lib/ld-2.9.so)
==24801== 
==24801== Conditional jump or move depends on uninitialised value(s)
==24801==    at 0x4016A63: (within /lib/ld-2.9.so)
==24801==    by 0x4005CF2: (within /lib/ld-2.9.so)
==24801==    by 0x400766C: (within /lib/ld-2.9.so)
==24801==    by 0x40010C4: (within /lib/ld-2.9.so)
==24801==    by 0x400E035: (within /lib/ld-2.9.so)
==24801==    by 0x4000F7B: (within /lib/ld-2.9.so)
==24801==    by 0x4003551: (within /lib/ld-2.9.so)
==24801==    by 0x40147B0: (within /lib/ld-2.9.so)
==24801==    by 0x4000C1C: (within /lib/ld-2.9.so)
==24801==    by 0x4000816: (within /lib/ld-2.9.so)
--24801-- Reading syms from /home/ddahl/lib/valgrind/x86-linux/vgpreload_memcheck.so (0x4023000)
--24801-- Reading syms from /lib/tls/i686/cmov/libc-2.9.so (0x4045000)
--24801-- Reading debug info from /lib/tls/i686/cmov/libc-2.9.so...
--24801-- ... CRC mismatch (computed 7ee64c88 wanted 8d898f0d)
--24801--    object doesn't have a symbol table
==24801== 
==24801== Conditional jump or move depends on uninitialised value(s)
==24801==    at 0x400BF23: (within /lib/ld-2.9.so)
==24801==    by 0x400325B: (within /lib/ld-2.9.so)
==24801==    by 0x40147B0: (within /lib/ld-2.9.so)
==24801==    by 0x4000C1C: (within /lib/ld-2.9.so)
==24801==    by 0x4000816: (within /lib/ld-2.9.so)
==24801== 
==24801== Conditional jump or move depends on uninitialised value(s)
==24801==    at 0x400A9EC: (within /lib/ld-2.9.so)
==24801==    by 0x400325B: (within /lib/ld-2.9.so)
==24801==    by 0x40147B0: (within /lib/ld-2.9.so)
==24801==    by 0x4000C1C: (within /lib/ld-2.9.so)
==24801==    by 0x4000816: (within /lib/ld-2.9.so)
==24801== 
==24801== Conditional jump or move depends on uninitialised value(s)
==24801==    at 0x400B6C1: (within /lib/ld-2.9.so)
==24801==    by 0x400325B: (within /lib/ld-2.9.so)
==24801==    by 0x40147B0: (within /lib/ld-2.9.so)
==24801==    by 0x4000C1C: (within /lib/ld-2.9.so)
==24801==    by 0x4000816: (within /lib/ld-2.9.so)
==24801== 
==24801== Conditional jump or move depends on uninitialised value(s)
==24801==    at 0x400A6C6: (within /lib/ld-2.9.so)
==24801==    by 0x4003364: (within /lib/ld-2.9.so)
==24801==    by 0x40147B0: (within /lib/ld-2.9.so)
==24801==    by 0x4000C1C: (within /lib/ld-2.9.so)
==24801==    by 0x4000816: (within /lib/ld-2.9.so)
==24801== 
==24801== Conditional jump or move depends on uninitialised value(s)
==24801==    at 0x400A6CE: (within /lib/ld-2.9.so)
==24801==    by 0x4003364: (within /lib/ld-2.9.so)
==24801==    by 0x40147B0: (within /lib/ld-2.9.so)
==24801==    by 0x4000C1C: (within /lib/ld-2.9.so)
==24801==    by 0x4000816: (within /lib/ld-2.9.so)
==24801== 
==24801== Conditional jump or move depends on uninitialised value(s)
==24801==    at 0x400A9EC: (within /lib/ld-2.9.so)
==24801==    by 0x4003364: (within /lib/ld-2.9.so)
==24801==    by 0x40147B0: (within /lib/ld-2.9.so)
==24801==    by 0x4000C1C: (within /lib/ld-2.9.so)
==24801==    by 0x4000816: (within /lib/ld-2.9.so)
--24801-- REDIR: 0x40bca60 (rindex) redirected to 0x40270e0 (rindex)
--24801-- REDIR: 0x40bbf00 (index) redirected to 0x40271d0 (index)
--24801-- REDIR: 0x40b8930 (malloc) redirected to 0x4026cd0 (malloc)
--24801-- REDIR: 0x40c1390 (strchrnul) redirected to 0x4028470 (strchrnul)
--24801-- REDIR: 0x40bc5e0 (strlen) redirected to 0x4027490 (strlen)
--24801-- REDIR: 0x40be850 (memcpy) redirected to 0x4027900 (memcpy)
--24801-- REDIR: 0x40be3a0 (mempcpy) redirected to 0x40284d0 (mempcpy)
--24801-- REDIR: 0x40bc070 (strcmp) redirected to 0x4027790 (strcmp)
--24801-- REDIR: 0x40b6520 (free) redirected to 0x4025af0 (free)
--24801-- REDIR: 0x40b8de0 (realloc) redirected to 0x4026de0 (realloc)
--24802-- REDIR: 0x40bc0e0 (strcpy) redirected to 0x40274f0 (strcpy)
--24803-- REDIR: 0x40bc0e0 (strcpy) redirected to 0x40274f0 (strcpy)
--24801-- REDIR: 0x40bc0e0 (strcpy) redirected to 0x40274f0 (strcpy)
zsh: segmentation fault  valgrind -v  -P opt-new --no-remote
ddahl-t500 139~/code/moz/mozilla-central/mozilla %
tiny tweak to unbitrot XRE_Main()
Attachment #395996 - Attachment is obsolete: true
this patch is building ok, actually. (After a clobber build)
Whiteboard: [ts]
Attachment #396281 - Attachment is obsolete: true
Just posting some crash stacks and output from the debugger. This seems to crash at random times and places, but I am looking for a pattern.
Vlad, what is this blocked on? Comment #62 sounds dead-end-y. Is there an 80% solution, that we could get now? Some timeline is better than no timeline.
This is an unbitrotted version of attachment 401985 [details] [diff] [review].
Attachment #401985 - Attachment is obsolete: true
ehsan wanted me to build on linux and attach backtrace
On a mac debug build, I got this assertion, which happens way earlier than the crash David is seeing:

#0      0x97ef1732 in __kill
#1      0x97ef1724 in kill$UNIX2003
#2      0x97f8498d in raise
#3      0x97f9aa44 in abort
#4      0x000a36ea in PR_Assert at prlog.c:625
#5      0x000bd266 in PR_NewLock at ptsynch.c:178
#6      0x000b1057 in _PR_InitStuff at prinit.c:177
#7      0x000b1275 in _PR_ImplicitInitialization at prinit.c:259
#8      0x000a2f2b in PR_NewLogModule at prlog.c:404
#9      0x0039cdb8 in __static_initialization_and_destruction_0 at nsTimerImpl.h:55
#10     0x0039cde2 in global constructors keyed to nsStringInputStream_classInfoGlobal at nsXPComInit.cpp:838
#11     0x8fe0ed6d in __dyld__ZN16ImageLoaderMachO18doModInitFunctionsERKN11ImageLoader11LinkContextE
#12     0x8fe0d31e in __dyld__ZN11ImageLoader23recursiveInitializationERKNS_11LinkContextEj
#13     0x8fe0d2c2 in __dyld__ZN11ImageLoader23recursiveInitializationERKNS_11LinkContextEj
#14     0x8fe0d2c2 in __dyld__ZN11ImageLoader23recursiveInitializationERKNS_11LinkContextEj
#15     0x8fe0d2c2 in __dyld__ZN11ImageLoader23recursiveInitializationERKNS_11LinkContextEj
#16     0x8fe0d3d1 in __dyld__ZN11ImageLoader15runInitializersERKNS_11LinkContextE
#17     0x8fe024a9 in __dyld__ZN4dyld24initializeMainExecutableEv
#18     0x8fe07950 in __dyld__ZN4dyld5_mainEPK12macho_headermiPPKcS5_S5_
#19     0x8fe018b1 in __dyld__ZN13dyldbootstrap5startEPK12macho_headeriPPKcl
#20     0x8fe01057 in __dyld__dyld_start
Ehsan:  I removed the instrumentation patch and re-built, the browser starts ok. I recommend making some new test instrumentation patches that are much small and localized to track down the culprit. On windows it was usually the observer instrumentation that crashed.
Actually it looks like the browser did hang for a few seconds, then quit ok. Weird. I will help debuig this more next week if you want.
(In reply to comment #75)
> Actually it looks like the browser did hang for a few seconds, then quit ok.
> Weird. I will help debuig this more next week if you want.

That would be wonderful, as I have not yet been able to get it to work.  :-(
Blocks: 447581
Attached patch updated code (obsolete) — Splinter Review
Ok, let's get this going again.  This doesn't use NSPR at all, so we don't have any of the problems associated with initialization or cross-process stuff; I'll make the JS side of things look for a symbol inside libxul first, but that's not included here.

This makes FunctionTimer.h globally available; bsmedberg, that look ok?
Assignee: ddahl → vladimir
Attachment #391737 - Attachment is obsolete: true
Attachment #435950 - Flags: review?(benjamin)
Comment on attachment 435950 [details] [diff] [review]
updated code

>diff --git a/xpcom/base/FunctionTimer.h b/xpcom/base/FunctionTimer.h

>+#ifndef NS_FUNCTIONTIMER_H__
>+#define NS_FUNCTIONTIMER_H__

nit, please use mozilla_FunctionTimer_h

>+/****
>+ **** KEEP THIS FILE IN SYNC WITH js/src/jsftimer.h !
>+ ****/

stale comment, I think? 

>+#include <stdarg.h>
>+#include <string.h>
>+
>+#include <prtime.h>
>+#include <prinit.h>

I'd prefer this code in general to use TimeStamps instead of PRTime, to get better resolution where available and also avoid clock-adjust and overflow issues which that class solves.


>+// Add a timer for this block, using the printf-style format.
>+// Both function entry and exit will be printed.
>+#define NS_TIME_FUNCTION_FMT(...)                                       \
>+    mozilla::FunctionTimer ft__autogen(__VA_ARGS__)

I'm fine with --enable-functiontimer requiring C99 variable-arg macros. I wish there were a configure test for them. Could you file a followup if there's not one already available?


>+namespace mozilla {
>+
>+class NS_COM FunctionTimerLog {

nit here and below, opening brace of class in column 0

>+public:
>+    FunctionTimerLog(const char *fname);

As noted on IRC, I can't find anyone constructing one of these, so I'm interested to know where the filename comes from (you said it was a mis-qrefeshed patch, perhaps)
Attachment #435950 - Flags: review?(benjamin)
Attached patch updated (obsolete) — Splinter Review
Ok, here's the updated framework, for real this time.

* mozilla/FunctionTimer.h
* uses TimeStamp

I had to change TimeStamp's initialization to use a static helper object, because xpcom init was too late for FunctionTimer's usage of it.  TimeStamp really isn't an XPCOM thing anyway (neither is FT, really).

https://wiki.mozilla.org/Platform/FunctionTimer_Usage has some usage instructions.  I'm still waiting for try server builds to finish, but that could be a while due to MV's internet problems.
Attachment #435950 - Attachment is obsolete: true
Attachment #439333 - Flags: review?
Attachment #439333 - Flags: review? → review?(benjamin)
Attached patch updated, v2Splinter Review
same as before, but fixes [v]sprintf usage due to #define shenanigans on all platforms.  builds on tryserver.
Attachment #439333 - Attachment is obsolete: true
Attachment #439649 - Flags: review?(benjamin)
Attachment #439333 - Flags: review?(benjamin)
I just realized that the TimeStamp usage means that this can't ever go into js. Hrm.  That's unfortunate, will have to work around that somehow.
Comment on attachment 439649 [details] [diff] [review]
updated, v2

>diff --git a/xpcom/base/FunctionTimer.cpp b/xpcom/base/FunctionTimer.cpp

>+// needed to get vsnprintf with glibc
>+#ifndef _XOPEN_SOURCE
>+#define _XOPEN_SOURCE 500
>+#endif

man pages say  _ISOC99_SOURCE works as well, can we use that? Tt seems clearer to me, at least until we can require c++0x.

>+struct TimerInitialization {

nit, opening brace of struct in column 0

I might be too pedantic, in which case ignore me, but I think this would be simpler to understand without the TimerInitialization class, and just use a function to initialize, e.g.

int FunctionTimer::sBufSize = FunctionTimer::InitTimers(); // static initialization (InitTimers returns int, not void)

>+int
>+FunctionTimer::ft_vsnprintf(char *str, int maxlen, const char *fmt, va_list args)
>+{
>+#ifdef _MSC_VER
>+    return _vsnprintf(str, maxlen, fmt, args);
>+#else
>+    return vsnprintf(str, maxlen, fmt, args);
>+#endif
>+}

In other files we typically use

#ifdef _MSC_VER
#define vsnprintf _vsnprintf
#endif

>diff --git a/xpcom/base/FunctionTimer.h b/xpcom/base/FunctionTimer.h

>+class NS_COM FunctionTimerLog {

nit, brace in column 0, same for FunctionTimer below

>diff --git a/xpcom/ds/TimeStamp.cpp b/xpcom/ds/TimeStamp.cpp
>--- a/xpcom/ds/TimeStamp.cpp
>+++ b/xpcom/ds/TimeStamp.cpp
>@@ -41,6 +41,17 @@
> 
> namespace mozilla {
> 
>+struct TimeStampInitialization {

ditto

>+  TimeStampInitialization() {
>+    TimeStamp::Startup();
>+  }
>+  ~TimeStampInitialization() {
>+    TimeStamp::Shutdown();
>+  }
>+};
>

Hrm, it seems silly to me to destroy this lock on shutdown. Why bother? But since it already is this way, that's ok.

r=me with nits/notes
Attachment #439649 - Flags: review?(benjamin) → review+
Checked in with fixes.

http://hg.mozilla.org/mozilla-central/rev/e3798bb6927d

I'm going to close this bug and file a new bug shortly for the instrumentation work.
Status: NEW → RESOLVED
Closed: 14 years ago
Resolution: --- → FIXED
bug 560647 is the tracking bug for instrumentation work.
Keywords: dev-doc-needed
(In reply to comment #85)
> I think this broke TB builds -
> http://tinderbox.mozilla.org/showlog.cgi?log=Thunderbird/1271796118.1271798200.32517.gz#err0

It may be better to characterize that as "Thunderbird's mozilla-central windows builds are on fire and it's possible this will be the case for Firefox too, but Thunderbird understands that mozilla-central does not and should not be concerned about breakage in comm-central if that does not turn out to be the case".
Er, yes, I'm just hoping for some hints as to why this broke TB and how to fix it. I think Firefox builds are fine, so perhaps there's some config change we need to make...
perhaps it's because we're building xpcom as a dll, at least in debug builds
putting the static char *sbuf2; on its own line seems to fix the issue here...
Depends on: 560715
Depends on: 560717
Target Milestone: --- → mozilla1.9.3a5
Attachment #440441 - Flags: review?(kairo)
Comment on attachment 440441 [details] [diff] [review]
(AAv1-CC) Copy it to comm-central
[Moved to bug 604849]

Do we win anything by having this in comm-central, i.e. do we need the NS_FUNCTION_TIMER var in application code? Or is this used in generic m-c code only anyhow?
Comment on attachment 440441 [details] [diff] [review]
(AAv1-CC) Copy it to comm-central
[Moved to bug 604849]

this needs a new bug; not reviewing here.
Attachment #440441 - Flags: review?(kairo)
Attachment #440441 - Flags: review?(bugspam.Callek)
Attachment #440441 - Flags: review-
(In reply to comment #92)

See "v 0.6 unbitrotted instrumentation patch" as an example:

> do we need the NS_FUNCTION_TIMER var in application code?

NS_FUNCTION_TIMER, no; but FunctionTimer.h (which depends on it), yes.

> Or is this used in generic m-c code only anyhow?

I assume (c-c) apps may want to use this tool too.

Vladimir, did I figured it out wrongly?
Attachment #440441 - Attachment description: (AAv1-CC) Copy it to comm-central → (AAv1-CC) Copy it to comm-central [Moved to bug 604849]
Attachment #440441 - Attachment is obsolete: true
Is this available in only core code, or can components use it?
fwiw, I've been looking at this code for a while, and it scares me enough that I would really prefer that someone else jot down notes or docs about this instead of trying to guess how this works. :)
You need to log in before you can comment on or make changes to this bug.