47207 - printfs and console window info needs to be boiled away for release builds

Status: RESOLVED WORKSFORME

(SeaMonkey :: General, defect, P1)

Description

[Judson Valeski]

Currently, in a release build, we still spit data to stdout (here's an example
http://lxr.mozilla.org/seamonkey/source/docshell/base/nsWebShell.cpp#207). the
registry does this too, as does the component loader. we need to fix this so
this data isn't pumped in release builds. On an appliance device w/ out a
console, this data gets queued up in memory and just grows.

Comment 1

[Judson Valeski]

I've cleaned up a bunch of these. dp please explain now the comp manager and
registry are spewing so I can fix those.

Comment 2

[Suresh Duddi (gone)]

I agree. But I see only one printf from xpcom/components that is not inside a
debug. If you find any, you can make them ifdef DEBUG.

Caution: Some of the printfs aren't inside DEBUG directly. They maybe called
only in debug or in some #if PRINT_CRITICAL_ERROR_TO_SCREEN You can turn those
off for embed builds.

Comment 3

[Judson Valeski]

note: there's no such thing as an "embed" build. we build off of mozilla.

Comment 4

[clayton]

P3 assuming that stdout goes to temp files and managable places on end-user 
machines.  Ugly, but not stop ship.  
For embedding, different story!

Comment 5

[lchiang]

per email with Jud, changing nsbeta3+ to nsbeta3- on all "embed" keyword bugs
since embedding changes will not be made in the mn6 branch. If you feel this bug
fix needs to go into mn6 branch, please list the reasons/user impact/risk and
nominate for rtm. Thanks.

Comment 6

[Warren Harris]

Jud: I almost think I want to take this one. Tell me I'm crazy.

Comment 7

[Judson Valeski]

you're crazy (and the new owner)! I nailed some of it, but we still spew like a
fountain.

Comment 8

[Doron Rosenberg (IBM)]

question - is this not nsonly?

Comment 9

[Judson Valeski]

Doron, if mozilla projects want to leak stdout/stderr output into the system
buffer for release builds, then yes, this is ns only. I'm working on a mozilla
project however where this is a *major* concern. Do you still feel this is ns only?

Comment 10

[Warren Harris]

When does this have to be done by?

My idea was to change printf(...) into PRINTF((...)) so that it can be 
controlled by a macro or nspr log module.

Comment 11

[Judson Valeski]

within the next couple of weeks.

I'm not sure printf if is the only offender.

Comment 12

[Doron Rosenberg (IBM)]

valeski - I misread you, sorry.  I mis understood 'release' as being commercial.

adding performance keyword

Comment 13

[Warren Harris]

I've got ~1.6M of diffs for this. Where do you want them?

Comment 14

[Judson Valeski]

holy cow! before distributing them, can you describe what you've done here?

Comment 15

[Warren Harris]

1. Replaced every printf with PRINTF (the bulk of the changes)
2. Added #include "nslog.h" to files with PRINTF
3. Implemented nslog.h in xpcom

Some features of this new logging facility:
a. Easier to use than PR_LOG
b. Log module per file (in many cases)
c. Scriptable logging
d. Logs can be redirected to other destinations
e. .nslog file for perminent log enabling

Comment 16

[Dan Mosedale (:dmosedale, :dmose)]

Would it be useful to migrate instead towards using something which implements
nsIConsoleService (perhaps renaming it as nsILogService or something) for
general logging purposes?  Since it supports circular an observer model, it's
suitable for both writing out to files and presenting partial, filtered results
to the end-user via GUI.  It also has a circular buffer which the embedded case
could make as tiny as it wants.

Comment 17

[Warren Harris]

Actually there's a lot of similarity between them. I wanted to make another 
pass after landing this initial stuff to see if I could unify them.

Comment 18

[Warren Harris]

I'm going to attach the first cut at the xpcom portion of the diffs for this so 
that people can get a flavor of the new system. The complete set of diffs are 
~1.6M and are mostly a pretty redundant replacement of printf with PRINTF.

From the combination of nslog.h and the xpcom diffs you'll be able to see both 
how the new logging stuff works, and how it gets used in various places within 
xpcom (e.g. the component manager). 

Things not done yet: 
- fix that all log objects are reported as leaked (they're globals that are held 
for the lifetime of the program, so this isn't critical, but we should fix)
- fix syntax/parsing of the .nslog file (still looking for the old 
NSPR_LOG_MODULES syntax with levels, etc.)
- unify nsILoggingService with nsIConsoleService
- verify that nsDebug.cpp still reports assertions and warnings correctly on mac

Comment 19

[Warren Harris]

Attachment: nslog.h -- C++ interface to logging with documentation

Comment 20

[Warren Harris]

Attachment: xpcom diffs for logging

Comment 21

[Chris Waterson]

warren say, "go big or go home"! Here's stuff I notice...

- "cvs diff -wu" will ignore whitespace changes. Might reduce the scariness
  of the patch a bit.

- I don't know if I like you taking over PR_ASSERT(). Why'd you do that?

- not sure the TEMP_MAC_HACK stuff is right; should talk to sfraser or
  whoever wrote it (in nsDebug.cpp)

- can't you "null out global" in nsLoggingService's dtor instead of
  requiring a special Release() implementation?

- do you want NS_GetLog() to be 'extern "C"' to avoid mangling? (who
  cares, I guess...)

- you left a some timing cruft in, search for PR_NewThreadPrivateIndex(). Is
  this in or out?

- is "#undef fprintf" required in nsTraceRefcnt.cpp

- won't your nsCOMPtr hackery in nsXPComInit.cpp break if we start unloading
  services?

- why did you turn off FORCE_PR_LOG in nsNativeComponentLoader.cpp?

- do you really need a different log module for every file (e.g., I notice
  that the component registry used to all log to the same PRLogModuleInfo;
  now they're broken out by file.)

- looks like the tabs got worse in bufferRoutines.h!

- nsAtomTable.cpp changes conditioned on both an environment variable and
  new log-fu; nuke getenv()?

- nsStatistics.cpp looks like it doesn't need *any* log-fu

- ibid, nsString2.cpp

- nsVoidBTree.cpp, logging seems like overkill here. There was a #ifdef DEBUG-
  only routine that used printf. It's not like this was going to be logged
  regularly...

- xpcom/io/MANIFEST_IDL changes are unrelated?

- nsDirectorService.cpp needs no logging

- nsFileSpec[BeOS|Unix].cpp howzabout just removing the printf altogether

- In general, I'm loathe to change stuff that's #ifdef DEBUG_foo or #ifdef
  BAR_DEBUG into logging. Someone wants to printf, let 'em.

I presume there's megabytes more where this came from?

Comment 22

[Warren Harris]

  + - "cvs diff -wu" will ignore whitespace changes. Might reduce the scariness
  +   of the patch a bit.
  +
  + - I don't know if I like you taking over PR_ASSERT(). Why'd you do that?

Whatever was in prlog.h...

  +
  + - not sure the TEMP_MAC_HACK stuff is right; should talk to sfraser or
  +   whoever wrote it (in nsDebug.cpp)

I'm going to test this on the mac, but I think TEMP_MAC_HACK is now obsolete.

  +
  + - can't you "null out global" in nsLoggingService's dtor instead of
  +   requiring a special Release() implementation?
  +
  + - do you want NS_GetLog() to be 'extern "C"' to avoid mangling? (who
  +   cares, I guess...)

I don't care. 

  +
  + - you left a some timing cruft in, search for PR_NewThreadPrivateIndex(). 
Is
  +   this in or out?

Out, I'll fix that.

  +
  + - is "#undef fprintf" required in nsTraceRefcnt.cpp

Yes, since nsTraceRefcnt can write to files. I think I may remove the #define 
fprintf altogether since nslog.h doesn't implement an alternative.

  +
  + - won't your nsCOMPtr hackery in nsXPComInit.cpp break if we start 
unloading
  +   services?

Not sure what you're talking about here.

  +
  + - why did you turn off FORCE_PR_LOG in nsNativeComponentLoader.cpp?

No longer needed.

  +
  + - do you really need a different log module for every file (e.g., I notice
  +   that the component registry used to all log to the same PRLogModuleInfo;
  +   now they're broken out by file.)

I can combine them, but that's how my automated editing whacked the files. 
Until someone really needs them to be combined, I'm probably not going to 
change them.

  +
  + - looks like the tabs got worse in bufferRoutines.h!

ugh

  +
  + - nsAtomTable.cpp changes conditioned on both an environment variable and
  +   new log-fu; nuke getenv()?

ok

  +
  + - nsStatistics.cpp looks like it doesn't need *any* log-fu

ok

  +
  + - ibid, nsString2.cpp

ok, although leaving it in is pretty harmless and may avoid the need to yank 
some printfs later.

  +
  + - nsVoidBTree.cpp, logging seems like overkill here. There was a #ifdef 
DEBUG-
  +   only routine that used printf. It's not like this was going to be logged
  +   regularly...

But it's harmless. I want to be consistent here.

  +
  + - xpcom/io/MANIFEST_IDL changes are unrelated?

Oops, old changes.

  +
  + - nsDirectorService.cpp needs no logging

true, but I'll leave it in

  +
  + - nsFileSpec[BeOS|Unix].cpp howzabout just removing the printf altogether

not my job

  +
  + - In general, I'm loathe to change stuff that's #ifdef DEBUG_foo or #ifdef
  +   BAR_DEBUG into logging. Someone wants to printf, let 'em.

No! Absolutely no printfs.

  +
  + I presume there's megabytes more where this came from?

Uh huh.

Comment 23

[Chris Waterson]

Here're the nsCOMPtr changes I was referring to:

+    // get the logging service so that it gets registered with the service
+    // manager, and later unregistered
+#ifdef NS_ENABLE_LOGGING
+    nsCOMPtr<nsILoggingService> logServ = do_GetService(kLoggingServiceCID, &rv);
+#endif

Ok, bring on the rest of those diffs.

Comment 24

[Chris Waterson]

r=waterson. as we'd discussed, probably the best way to get these in (to verify
that no compilers barf on e.g. nsNoop) is to get all the core log stuff built
and linking, and then land one file into the tree. Let it shake out overnight
(so all the ports can tinker with it if need be), and then send the rest of the
changes in.

Comment 25

[Scott Collins]

I think we care about more than |nsNoop| not causing horkage.  We care that it
does what we want ... optimizes away.  What happens in the no-inlining case (not
quite sure we care about that)?  What happens if argument evaluation would have
side-effects?  I'll bet the compiler is not allowed to optimize away their
evaluation, in that case.  |nsNoop| is, to me, the scariest part of the patch.

Comment 26

[Brendan Eich [:brendan]]

Warren, you spanker! ;-)  Don't you have better things to do than court trouble
with nsNoop?  Why not use ye olde double-parenthesization?

/be

Comment 27

[Scott Collins]

yeah!  double parentheses like

  NS_PRINTF((stuff, "more stuff", 5, a, b));

We _know_ how to make that optimize totally away, and it's not that far away
from what you've got now.  I should have remembered that before we ever talked
about it, Brendan, and I certainly should have brought it up here after you
mentioned it in our first discussion of this patch.

Comment 28

[Warren Harris]

Double parens is the fallback strategy. But I think it's important to 
investigate whether we can make this work -- it lowers the barrier to entry for 
the PR_LOG adverse.

I'm going to follow the checkin strategy Chris and I discussed. That will allow 
us to easily back it out if we find problems. 

Comment 29

[Chris Waterson]

Yeah, but as scc notes, the compiler probably won't optimize away function
calls; e.g., the optimizer has no clue that NS_ConvertUCS2toUTF8 has no side
effects in the following example:

  PRUnichar* foo = /* something */;
  PRINTF("the value is %s", NS_ConvertUCS2toUTF8(foo));

Comment 30

[Brendan Eich [:brendan]]

((                        ))
((                        ))
(())        (())        (())
(())        (())        (())    (())    (((())))   (((())))   (((()))) ()    ()
((()))     ((  ))     ((()))   ((  ))   ((     ))  ((     ))  ()       ()()  ()
(((())))  ((    ))  (((())))  (((())))  ((((())))  ((((())))  (((()))) () () ()
(((((())))))    (((((()))))) ((      )) ((      )) ((      )) ()       ()  ()()
(((((())))))    (((((()))))) ((      )) ((      )) ((      )) (((()))) ()    ()

We've got lots of parentheses, buckets of 'em, cheaper by the dozen!  Come on 
down!  Crazy Brendan's!

/be

Comment 31

[Warren Harris]

You were a lisper... I know it!!!

Comment 32

[Scott MacGregor]

I'd like to ask a dumb question....why can't I have
#ifdef DEBUG_mscott
	print out some helpful debugging information for my piece of code?
#endif

You say absolutely no printfs, but I don't understand why the pattern listed
above is bad? I use this in lots of places were I don't want to use logging.

Comment 33

[Warren Harris]

It's not bad, but I think using PRINTF is better. See the notes I just posted to 
mozilla-seamonkey.

Comment 34

[Warren Harris]

Ok, the combination of Brendan and the problem we had with #ifdef DEBUG -only 
variables being defined convinced me that we should do the double paren fu:

   PRINTF("hello");  =>  PRINTF(("hello")); 

I hope that doesn't deter people too much from using this.

Comment 35

[Peter Van der Beken]

This breaks the build on Macintosh with MOZ_SVG defined.

Error   : macro 'PRINTF' redefined
nsCSSFrameConstructor.cpp line 129   #define PRINTF 
NS_LOG_PRINTF(nsCSSFrameConstructorLog)

Error   : macro 'FLUSH' redefined
nsCSSFrameConstructor.cpp line 130   #define FLUSH  
NS_LOG_FLUSH(nsCSSFrameConstructorLog)

It doesn't break regular builds because the logging stuff was put in an #ifdef 
MOZ_SVG block.

#ifdef MOZ_SVG
#include "nsSVGAtoms.h"
...
#include "nslog.h"

NS_IMPL_LOG(nsCSSFrameConstructorLog)
#define PRINTF NS_LOG_PRINTF(nsCSSFrameConstructorLog)
#define FLUSH  NS_LOG_FLUSH(nsCSSFrameConstructorLog)
...
#endif

Comment 36

[Peter Van der Beken]

I think the error is caused by the defines in mozilla/layout/html/forms/src/
nsFormControlFrame.h:

...
#include "nslog.h"

NS_DECL_LOG(nsFormControlFrameLog)
#define PRINTF NS_LOG_PRINTF(nsFormControlFrameLog)
#define FLUSH  NS_LOG_FLUSH(nsFormControlFrameLog)
...

Comment 37

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

In a build with lots of things enabled, (--enable-mathml, --enable-svg,
--enable-nspr-autoconf, --with-extensions=all, --enable-perf-metrics), I hit
bustage in nsViewerApp.cpp related to the redefinition of PR_ASSERT.

nsViewerApp.cpp includes nsVector.h which includes plvector.h which uses
PR_ASSERT in PL_VectorGetAddr.  Some preprocessor output showing a problem that
gives a parse error (lines 54-56 of nsVector.h) is:

    void* Get(PRUint32 indx) const { return (*(if (!((indx) < (this)->size))
nsDebug::Assertion("(indx) < (this)->size", "(indx) < (this)->size",
"../../../dist/include/nsVector.h", 54), &(this)->data[indx])); }
    void Set(PRUint32 indx, void* newElement) { PL_VectorSet(this, indx,
newElement); }
    void*& ElementAt(PRUint32 indx) { return *(if (!((indx) < (this)->size))
nsDebug::Assertion("(indx) < (this)->size", "(indx) < (this)->size",
"../../../dist/include/nsVector.h", 56), &(this)->data[indx]); }

Comment 38

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

What's the status of these changes?  Is someone going to finish up this work?
If not, should we back out what's the bit that's already in or leave it as is?

Comment 39

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Well, for lack of any response, I'm going to propose the "back out what's
already there" approach, for the following reasons:

 * nobody seems to want to finish it, and it's not doing very much being used in
one or two files

 * It causes a majority (I think) of the assertions triggered by my patch in bug
62006 (assertions about static constructors), so if these assertions are ever
going to be useful, we'd need to get rid of it.  (This assumes we still want to
get rid of static constructors -- they prevent us from running on OpenBSD, they
cause issues with DLL unloading, and they confuse the leak stats.)

 * It seems to be causing problems for some users of parts (XPCOM+netwerk) of
the mozilla code (see bug 62097)

 * It shows up in the leak stats (making it a little harder to see real leaks)
and uses a bit of memory (bug 58966)

Comment 40

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

The current presence of the logging changes in the tree is in the following 4
files in xpcom/base:  nslog.h, nsLogging.h, nsLogging.cpp, and
nsILoggingService.idl, plus references to those files in a few other files (I'll
attach a patch that removes those, except for removing from the Mac build) and
nsStopwatch.cpp.

Comment 41

[Judson Valeski]

david, works for me. can you review the following attatched patch which removes
an unneeded printf?

Comment 42

[Judson Valeski]

Attachment: removal of extraneous printf

Comment 43

[timeless]

r=timeless

Comment 44

[Simon Fraser [no longer active]]

sr=sfraser on the printf removal in editor

Comment 45

[Judson Valeski]

nsEditor.cpp printf removal checked in.

Comment 46

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: patch to remove nsLogging from the build

Comment 47

[Judson Valeski]

*** Bug 66223 has been marked as a duplicate of this bug. ***

Comment 48

[Marek Z. Jeziorek]

Cathleen, please add this bug to the blocker list of your "bloat bug" that you 
create.

Comment 49

[[e-mail]]

Sorry if this is the wrong place to mention it.

There are still some ways to consistently crash Mozilla. One of these is to
write invalid XUL. But fortunately just before Mozilla crashes it dumps an error
message to the console. I hope these messages don't go away from release builds
too soon.

Comment 50

[Jaime Rodriguez, Jr.]

Removing adequated PDT grafitti.  

Comment 51

[Andrew Schultz]

Is this still relevant (it seems not)?

Comment 52

[Mats Palmgren (inactive)]

Please open a new bug report if this is still a problem.

-> WORKSFORME