[b2g] Log collection needs improvement

[Al Tsai]

Hi all, 

I am sending this e-mail to start a discussion about current log mechanism. As 
you might know that we have different ways to collect logs, most kinds of logs 
need extra actions to enable them since performance issues. With more devices 
and users, the issues reported may not always come with solid STR (steps to 
reproduce). Some automation tests (such as MTBF and Orangutan Test) will not 
always have STR. Worse than that, the logs collected during testing contain no 
clues for resolving issues most of the time. 

Currently, the information we can get by "adb logcat" command is about WiFi. 
We'll need to use special methods to trigger RIL and it's not known by public. 
For Gaia logs, we'll need to reach the developers to know how to trigger its 
logger, or there's no logger due to performance concern. Within offline discuss 
with Tim, a centralized log mechanism control by the system app could be a 
solution. Or we can implement the log server inside gecko, direct all 
configuration to gecko, and let gecko decide when to drop logs. 

More thoughts are welcome. 

Best Regards, 
Al 
-- 

Al Tsai 
Senior QA Engineer, MoCo Taiwan 
Tel: +886-2-87861100 ext.358 
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[James Lal]

+sicking, +jst, +paul

So over the last few weeks I have had various discussions with people about
"logging" (there are metrics and log like data and bunch of random stuff
across gecko/gonk/gaia that fit other names too) we really badly need sane
logging data that is reachable by some single source. This is needed for a
couple of critical things:

 - debugging
 - tests
 - logs on other peoples phones [dogfooding builds] (another form of
debugging but you don't have the device.)

 We not only need a place to input data (in a wide reaching way) but also
nice apis for extracting that data (automation, periodic server side dumps,
crazy random new things).

Our current situation is pretty awful (I can list the reasons but those
involved likely know what I am talking about) and we need to unify efforts
to build something better... I spoke with jst about this recently and we
are trying to find the right person to fix this. If you feel super
excited/angry about logging get in touch with one/any/all of us so we can
mentor/bribe/help you through this.

- james

On Wed, Aug 20, 2014 at 8:09 PM, Al Tsai  wrote:

> Hi all,
>
> I am sending this e-mail to start a discussion about current log
> mechanism. As you might know that we have different ways to collect logs,
> most kinds of logs need extra actions to enable them since performance
> issues. With more devices and users, the issues reported may not always
> come with solid STR (steps to reproduce). Some automation tests (such as
> MTBF and Orangutan Test) will not always have STR. Worse than that, the
> logs collected during testing contain no clues for resolving issues most of
> the time.
>
> Currently, the information we can get by "adb logcat" command is about
> WiFi. We'll need to use special methods to trigger RIL and it's not known
> by public. For Gaia logs, we'll need to reach the developers to know how to
> trigger its logger, or there's no logger due to performance concern. Within
> offline discuss with Tim, a centralized log mechanism control by the system
> app could be a solution. Or we can implement the log server inside gecko,
> direct all configuration to gecko, and let gecko decide when to drop logs.
>
> More thoughts are welcome.
>
> Best Regards,
> Al
> --
>
> Al Tsai
> Senior QA Engineer, MoCo Taiwan
> Tel: +886-2-87861100 ext.358
>
> ___
> dev-b2g mailing list
> dev-b2g@lists.mozilla.org
> https://lists.mozilla.org/listinfo/dev-b2g
>
>
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Tim Chien]

Thanks Al for raising the issue.

To clarify, I didn't say log switch should be "centralized" in System
app. It should be centralized in Gecko.

Gaia developers are specifically told not to use |console.log/error|
etc. for normal operations because it comes with performance penalty.
It sounds like this ended up shoot us in the foot because of these
testing needs. What I am looking at is somehow enable us to add logs
in Gaia regardless, and introduce a pref in Gecko to turn them on or
off. When it's turned off we should not have any performance penalty.

Previously we had a creative invention from Frsela that turning on/off
a all-caps DUMP() function with mozSettings. I would love that being
formalized in Gecko.
https://github.com/mozilla-b2g/gaia/blob/master/shared/js/dump.js

Is that possible?

(PS |console.log| does not comes with the right order if the code
throws -- not sure if that can be fixed too.)


On Thu, Aug 21, 2014 at 12:16 PM, James Lal  wrote:
> +sicking, +jst, +paul
>
> So over the last few weeks I have had various discussions with people about
> "logging" (there are metrics and log like data and bunch of random stuff
> across gecko/gonk/gaia that fit other names too) we really badly need sane
> logging data that is reachable by some single source. This is needed for a
> couple of critical things:
>
>  - debugging
>  - tests
>  - logs on other peoples phones [dogfooding builds] (another form of
> debugging but you don't have the device.)
>
>  We not only need a place to input data (in a wide reaching way) but also
> nice apis for extracting that data (automation, periodic server side dumps,
> crazy random new things).
>
> Our current situation is pretty awful (I can list the reasons but those
> involved likely know what I am talking about) and we need to unify efforts
> to build something better... I spoke with jst about this recently and we are
> trying to find the right person to fix this. If you feel super excited/angry
> about logging get in touch with one/any/all of us so we can
> mentor/bribe/help you through this.
>
> - james
>
> On Wed, Aug 20, 2014 at 8:09 PM, Al Tsai  wrote:
>>
>> Hi all,
>>
>> I am sending this e-mail to start a discussion about current log
>> mechanism. As you might know that we have different ways to collect logs,
>> most kinds of logs need extra actions to enable them since performance
>> issues. With more devices and users, the issues reported may not always come
>> with solid STR (steps to reproduce). Some automation tests (such as MTBF and
>> Orangutan Test) will not always have STR. Worse than that, the logs
>> collected during testing contain no clues for resolving issues most of the
>> time.
>>
>> Currently, the information we can get by "adb logcat" command is about
>> WiFi. We'll need to use special methods to trigger RIL and it's not known by
>> public. For Gaia logs, we'll need to reach the developers to know how to
>> trigger its logger, or there's no logger due to performance concern. Within
>> offline discuss with Tim, a centralized log mechanism control by the system
>> app could be a solution. Or we can implement the log server inside gecko,
>> direct all configuration to gecko, and let gecko decide when to drop logs.
>>
>> More thoughts are welcome.
>>
>> Best Regards,
>> Al
>> --
>>
>> Al Tsai
>> Senior QA Engineer, MoCo Taiwan
>> Tel: +886-2-87861100 ext.358
>>
>> ___
>> dev-b2g mailing list
>> dev-b2g@lists.mozilla.org
>> https://lists.mozilla.org/listinfo/dev-b2g
>>
>
>
> ___
> dev-b2g mailing list
> dev-b2g@lists.mozilla.org
> https://lists.mozilla.org/listinfo/dev-b2g
>



-- 
Tim Guan-tin Chien, Engineering Manager and Front-end Lead, Firefox
OS, Mozilla Corp. (Taiwan)
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Gabriele Svelto]

On 21/08/2014 08:21, Tim Chien wrote:
> Previously we had a creative invention from Frsela that turning on/off
> a all-caps DUMP() function with mozSettings. I would love that being
> formalized in Gecko.
> https://github.com/mozilla-b2g/gaia/blob/master/shared/js/dump.js

Standardizing all gaia applications on DUMP() would already be a big
improvement even though the interface is currently very simple. Gecko
has similar problems regarding logging with certain components being
well made and others a total mess (often dumping output via 3/4
different unrelated methods). Also, the most common mechanism used in
C++ code (PR_Log) is not available under chrome code and thus we
normally resort to ad hoc logging solutions there (see the RIL component
for example).

 Gabriele



signature.asc
Description: OpenPGP digital signature
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Tim Chien]

On Thu, Aug 21, 2014 at 4:01 PM, Gabriele Svelto  wrote:
> On 21/08/2014 08:21, Tim Chien wrote:
>> Previously we had a creative invention from Frsela that turning on/off
>> a all-caps DUMP() function with mozSettings. I would love that being
>> formalized in Gecko.
>> https://github.com/mozilla-b2g/gaia/blob/master/shared/js/dump.js
>
> Standardizing all gaia applications on DUMP() would already be a big
> improvement even though the interface is currently very simple. Gecko
> has similar problems regarding logging with certain components being
> well made and others a total mess (often dumping output via 3/4
> different unrelated methods). Also, the most common mechanism used in
> C++ code (PR_Log) is not available under chrome code and thus we
> normally resort to ad hoc logging solutions there (see the RIL component
> for example).
>
>  Gabriele
>

Yeah, but that would mean every app need to read that mozSettings
value (and have the permission to access that) right? Plus log will
not appear during app start-up until the mozSettings get() returns
positive value.

I may be naive but I would really love that being done in Gecko...

-- 
Tim Guan-tin Chien, Engineering Manager and Front-end Lead, Firefox
OS, Mozilla Corp. (Taiwan)
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Andreas Gal]

console.log doesn’t have to be slow. Its only slow in Gecko. Its ridiculously 
fast in Chrome. We should probably simply optimize it.

Andreas

On Aug 21, 2014, at 8:47 AM, Tim Chien  wrote:

> On Thu, Aug 21, 2014 at 4:01 PM, Gabriele Svelto  wrote:
>> On 21/08/2014 08:21, Tim Chien wrote:
>>> Previously we had a creative invention from Frsela that turning on/off
>>> a all-caps DUMP() function with mozSettings. I would love that being
>>> formalized in Gecko.
>>> https://github.com/mozilla-b2g/gaia/blob/master/shared/js/dump.js
>> 
>> Standardizing all gaia applications on DUMP() would already be a big
>> improvement even though the interface is currently very simple. Gecko
>> has similar problems regarding logging with certain components being
>> well made and others a total mess (often dumping output via 3/4
>> different unrelated methods). Also, the most common mechanism used in
>> C++ code (PR_Log) is not available under chrome code and thus we
>> normally resort to ad hoc logging solutions there (see the RIL component
>> for example).
>> 
>> Gabriele
>> 
> 
> Yeah, but that would mean every app need to read that mozSettings
> value (and have the permission to access that) right? Plus log will
> not appear during app start-up until the mozSettings get() returns
> positive value.
> 
> I may be naive but I would really love that being done in Gecko...
> 
> -- 
> Tim Guan-tin Chien, Engineering Manager and Front-end Lead, Firefox
> OS, Mozilla Corp. (Taiwan)
> ___
> dev-b2g mailing list
> dev-b2g@lists.mozilla.org
> https://lists.mozilla.org/listinfo/dev-b2g

___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Fabrice Desré]

On 08/21/2014 07:51 AM, Andreas Gal wrote:
> 
> console.log doesn’t have to be slow. Its only slow in Gecko. Its ridiculously 
> fast in Chrome. We should probably simply optimize it.

Yes, it's very ancient code. I think when I tweaked the buffering to
limit memory usage some parts had not been touched since... the CVS import!

I think it's a nice project for someone that want to get his/her hands
dirty with gecko stuff.

Fabrice
-- 
Fabrice Desré
b2g team
Mozilla Corporation
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Dave Hylands]

There is also the issue of turning the logs on/off. 

I've come to like the ability to use android properties, since you can 
manipulate them from the adb shell command line using getprop/setprop. 

Using preferences is nice on the desktop, because we have a UI that can be used 
to control them. That same UI is currently unavailable on the phone. 

The only reason I would use mozSettings is if I wanted some gaia UI to be able 
to control things. 

We already have code to allow changes in a mozSetting to update a preference 
and vice-versa. I'd like to propose that we allow properties to also be 
updated/have changes reflected in preferences as well. 

The reason console.log has issues is that console.log requests made by a child 
are passed via IPC to the parent, and then they're logged. 
With dump() the call to the android logger happens in the child. 

linux has an interesting approach to system logging. Everybody uses syslog, and 
then there is a configuration file/daemon that takes care of actually 
distributing the log data. On the phone, logcat already takes care of the hard 
part. We just need to be a bit more clever about integrating things. Right now, 
all dump calls come out tagged as "Gecko". It probably makes sense to tag dump 
statements from an app using the app name. Then you'd be able to filter your 
logcat output and just get dumps from a particular app. You can get some very 
interesting logcat filters. I have a script that automatically does: 

adb logcat -v threadtime memalloc:I ONCRPC:S HWComposer:S Diag_Lib:S QCALOG:S 
QCRIL_RPC:S EventHub:I OMX.google.mp3.decoder:V 

You can add logging categories with :S to silence a particular category (or use 
*:S to silence everything) and then add back stuff you're interested in. Run 
adb logcat -h to get full details on filterspecs. 

If we want the ability to put the logging data off-device, then it probably 
makes sense to have a daemon that grabs data from logcat and sends it whereever 
it is that it needs to go. 

Dave Hylands 

- Original Message -

> From: "Tim Chien" 
> To: "Gabriele Svelto" 
> Cc: "dev-b2g" , "qa-b2g" ,
> "Johnny Stenback" , "Al Tsai" , "James
> Lal" , "Jonas Sicking" 
> Sent: Thursday, August 21, 2014 7:47:13 AM
> Subject: Re: [b2g] Log collection needs improvement

> On Thu, Aug 21, 2014 at 4:01 PM, Gabriele Svelto  wrote:
> > On 21/08/2014 08:21, Tim Chien wrote:
> >> Previously we had a creative invention from Frsela that turning on/off
> >> a all-caps DUMP() function with mozSettings. I would love that being
> >> formalized in Gecko.
> >> https://github.com/mozilla-b2g/gaia/blob/master/shared/js/dump.js
> >
> > Standardizing all gaia applications on DUMP() would already be a big
> > improvement even though the interface is currently very simple. Gecko
> > has similar problems regarding logging with certain components being
> > well made and others a total mess (often dumping output via 3/4
> > different unrelated methods). Also, the most common mechanism used in
> > C++ code (PR_Log) is not available under chrome code and thus we
> > normally resort to ad hoc logging solutions there (see the RIL component
> > for example).
> >
> > Gabriele
> >

> Yeah, but that would mean every app need to read that mozSettings
> value (and have the permission to access that) right? Plus log will
> not appear during app start-up until the mozSettings get() returns
> positive value.

> I may be naive but I would really love that being done in Gecko...

> --
> Tim Guan-tin Chien, Engineering Manager and Front-end Lead, Firefox
> OS, Mozilla Corp. (Taiwan)
> ___
> dev-b2g mailing list
> dev-b2g@lists.mozilla.org
> https://lists.mozilla.org/listinfo/dev-b2g
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Tim Chien]

On Fri, Aug 22, 2014 at 12:19 AM, Fabrice Desré  wrote:
> On 08/21/2014 07:51 AM, Andreas Gal wrote:
>>
>> console.log doesn’t have to be slow. Its only slow in Gecko. Its 
>> ridiculously fast in Chrome. We should probably simply optimize it.
>
> Yes, it's very ancient code. I think when I tweaked the buffering to
> limit memory usage some parts had not been touched since... the CVS import!
>
> I think it's a nice project for someone that want to get his/her hands
> dirty with gecko stuff.

What's the action item here? Should I file a bug and point to someone?
Who is that someone?
We definitely need this improved so we could put more log to fulfill
the testing needs.

-- 
Tim Guan-tin Chien, Engineering Manager and Front-end Lead, Firefox
OS, Mozilla Corp. (Taiwan)
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Mike Habicher]

  
  
On 14-08-26 02:00 AM, Tim Chien wrote:


  On Fri, Aug 22, 2014 at 12:19 AM, Fabrice Desré  wrote:

  
On 08/21/2014 07:51 AM, Andreas Gal wrote:


  
console.log doesn’t have to be slow. Its only slow in Gecko. Its ridiculously fast in Chrome. We should probably simply optimize it.



Yes, it's very ancient code. I think when I tweaked the buffering to
limit memory usage some parts had not been touched since... the CVS import!

I think it's a nice project for someone that want to get his/her hands
dirty with gecko stuff.

  
  
What's the action item here? Should I file a bug and point to someone?
Who is that someone?
We definitely need this improved so we could put more log to fulfill
the testing needs.




Somewhat related: bug
  881389 has been around for a while, but hasn't received a lot
of attention since jlebar left..

--m.

  

___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Ting-Yu Chou]

- Original Message -
> From: "Tim Chien" 
> To: "Fabrice Desré" 
> Cc: "dev-b2g" , "qa-b2g" , 
> "Jonas Sicking" ,
> "Andreas Gal" , "Al Tsai" , "Gabriele 
> Svelto" , "James
> Lal" , "Johnny Stenback" 
> Sent: Tuesday, August 26, 2014 2:00:11 PM
> Subject: Re: [b2g] Log collection needs improvement
> 
> On Fri, Aug 22, 2014 at 12:19 AM, Fabrice Desré  wrote:
> > On 08/21/2014 07:51 AM, Andreas Gal wrote:
> >>
> >> console.log doesn’t have to be slow. Its only slow in Gecko. Its
> >> ridiculously fast in Chrome. We should probably simply optimize it.
> >
> > Yes, it's very ancient code. I think when I tweaked the buffering to
> > limit memory usage some parts had not been touched since... the CVS import!
> >
> > I think it's a nice project for someone that want to get his/her hands
> > dirty with gecko stuff.
> 
> What's the action item here? Should I file a bug and point to someone?
> Who is that someone?
> We definitely need this improved so we could put more log to fulfill
> the testing needs.

Improving console.log looks interesting to me, I found also a bug 1045715 seems
related.

> 
> --
> Tim Guan-tin Chien, Engineering Manager and Front-end Lead, Firefox
> OS, Mozilla Corp. (Taiwan)
> ___
> dev-b2g mailing list
> dev-b2g@lists.mozilla.org
> https://lists.mozilla.org/listinfo/dev-b2g
> 
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Eric Rahm]

On 8/26/14 8:06 AM, Mike Habicher wrote:

On 14-08-26 02:00 AM, Tim Chien wrote:

On Fri, Aug 22, 2014 at 12:19 AM, Fabrice Desré  wrote:

On 08/21/2014 07:51 AM, Andreas Gal wrote:

console.log doesn’t have to be slow. Its only slow in Gecko. Its ridiculously 
fast in Chrome. We should probably simply optimize it.

Yes, it's very ancient code. I think when I tweaked the buffering to
limit memory usage some parts had not been touched since... the CVS import!

I think it's a nice project for someone that want to get his/her hands
dirty with gecko stuff.

What's the action item here? Should I file a bug and point to someone?
Who is that someone?
We definitely need this improved so we could put more log to fulfill
the testing needs.



Somewhat related: bug 881389
 has been around
for a while, but hasn't received a lot of attention since jlebar left..

--m.



I'm interested in following up on the "one true logger" in gecko and 
have been given the go-ahead to dedicate some time to it. I'll comment 
more on the bug.


To add to the discussion on gaia logging, if it were up to me I would 
want something like the following:

  * output should include some nice metadata (app/component, log level)
  * output should go to logcat if on a B2G device
  * output should go to debug console if not on a B2G device
  * levels should be configurable via UI and command-line

Below is an attempt to gather together the various topics discussed so 
far, please feel free to elaborate, add etc.


#1 - Gaia needs a better unified logging mechanism

Key feature required:
* One logging component usable by all Gaia applications

Possible options:
* dump() is the current defacto logger as far as I understand, I
  assume it can't be toggled on and off
* DUMP() existed (or exists) and was able to be disabled, we could
  build off of that
* console.log is a more standard solution but is "slow":
  I'm not sure how much this matters, it depends what slow means. Does
  it take a while for the log to show up, does it cost a lot of CPU
  (even when not being viewed), does it actually have a lot of overhead
  for the calling application?

  How does application level filtering work with console.log? Are
  console.log statements written to logcat as well?

#2 - Gaia needs the ability to specify log levels

Key features required:
* Need to be able to dynamically set the log levels
* Should work during application startup

Possible options:
* use mozSettings to enable logging, it has been noted that this will
  not work during app startup. Maybe that's okay.
* use android properties, it seems like this would be limited to actual
  devices w/ root access. I don't know if this has the same startup
  issues.

#3 - Gecko needs a better unified logging mechanism

Discussion and details can be found in bug 881389

-e
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Jonas Sicking]

On Wed, Aug 27, 2014 at 12:14 PM, Eric Rahm  wrote:
> * console.log is a more standard solution but is "slow":
>   I'm not sure how much this matters, it depends what slow means. Does
>   it take a while for the log to show up, does it cost a lot of CPU
>   (even when not being viewed), does it actually have a lot of overhead
>   for the calling application?

I don't understand why one logging function would need to be slower
than another logging function. I.e. why would

console.log("displaying frobber");

need to be any slower than

newFangledLog("displaying frobber");
or
dump("displaying frobber");

The fact that console.log is slow right now is probably due to how we
have implemented it, not due to the way the API is designed. It seems
preferable to me to change the implementation of console.log rather
than write a new implementation of a new logging function.

The only reason I could see why console.log is slower is if there's so
many existing callsites of console.log that if we make it actually log
the way we want to log, that we'd end up logging so much information
that that would be a problem. But it doesn't sound like that is the
concern that people have with console.log.

So, in short, I think we should look at making console.log faster
rather than introducing a new API.

/ Jonas
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Eric Rahm]

On 8/27/14 2:59 PM, Jonas Sicking wrote:

On Wed, Aug 27, 2014 at 12:14 PM, Eric Rahm  wrote:

* console.log is a more standard solution but is "slow":
   I'm not sure how much this matters, it depends what slow means. Does
   it take a while for the log to show up, does it cost a lot of CPU
   (even when not being viewed), does it actually have a lot of overhead
   for the calling application?


I don't understand why one logging function would need to be slower
than another logging function. I.e. why would

console.log("displaying frobber");

need to be any slower than

newFangledLog("displaying frobber");
or
dump("displaying frobber");

The fact that console.log is slow right now is probably due to how we
have implemented it, not due to the way the API is designed. It seems
preferable to me to change the implementation of console.log rather
than write a new implementation of a new logging function.

The only reason I could see why console.log is slower is if there's so
many existing callsites of console.log that if we make it actually log
the way we want to log, that we'd end up logging so much information
that that would be a problem. But it doesn't sound like that is the
concern that people have with console.log.

So, in short, I think we should look at making console.log faster
rather than introducing a new API.

/ Jonas



I agree, using console.log and friends makes sense. I'm not really sure 
I follow the "it's slower" argument (I was just restating it). Slowness 
of logging -- I assume that means amount of time from writing a log 
entry to displaying it -- just really shouldn't matter. Sure it would be 
good to fix, but it shouldn't prevent us from using console logging.


It just depends what slower means, it might mean "lots of overhead" or 
"literally my application is blocked for N ms while trying to log," that 
needs to be determined.


As Dave Hylands pointed out, all console.* functions currently get 
proxied to the main process. So there's IPC and memory overhead that can 
have a serious impact. Now that is a legitimate reason not to use 
console logging.


We can avoid that if we add some way to prevent console logging from 
being proxied if that application's log is disabled, or if the log level 
isn't high enough. Currently I don't think that's possible (I may be 
wrong about this), so we'd need to modify the console logging 
functionality. In a more extreme case on b2g we could just not proxy the 
logs at all and basically do a dump() but with prettier formatting.


Further functionality we would need to add is pumping out the console 
log to logcat on b2g devices (and presumably adding a proper component 
name).


-e
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Jonas Sicking]

On Wed, Aug 27, 2014 at 4:45 PM, Eric Rahm  wrote:
> It just depends what slower means, it might mean "lots of overhead" or
> "literally my application is blocked for N ms while trying to log," that
> needs to be determined.

I got the impression that the problem was "application is blocked for
N ms", which seems like a fixable implementation bug.

> As Dave Hylands pointed out, all console.* functions currently get proxied
> to the main process. So there's IPC and memory overhead that can have a
> serious impact. Now that is a legitimate reason not to use console logging.

I don't think sending the data to the parent process is a problem. As
long as we don't synchronously block while that IPC is happening.
Simply sending the data asynchronously and then immediately return to
the calling JS should mean that the IPC is causing no problem.

If we want to do anything useful with the data it most likely needs to
go to the parent process anyway. Child processes never have permission
to directly write to files, and of course any UI that lives outside of
the application is handled by other processes, which means that it has
to at least go through the main process.

> We can avoid that if we add some way to prevent console logging from being
> proxied if that application's log is disabled, or if the log level isn't
> high enough. Currently I don't think that's possible (I may be wrong about
> this), so we'd need to modify the console logging functionality. In a more
> extreme case on b2g we could just not proxy the logs at all and basically do
> a dump() but with prettier formatting.

Doesn't dump() also send the data to the parent process eventually?

/ Jonas
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Gabriele Svelto]

On 28/08/2014 01:56, Jonas Sicking wrote:
> I got the impression that the problem was "application is blocked for
> N ms", which seems like a fixable implementation bug.

Indeed and besides we've always got the option to easily turn off
logging at runtime in JS code (like DUMP() does for instance) so I think
we can live with some limited slow-down only when logging is enabled.
Having the ability to turn it on on a non-debug build dwarfs the
downsides IMHO.

> I don't think sending the data to the parent process is a problem. As
> long as we don't synchronously block while that IPC is happening.
> Simply sending the data asynchronously and then immediately return to
> the calling JS should mean that the IPC is causing no problem.

IPC is quite expensive in general on our implementation so even when
it's non-blocking it does have a measurable performance impact on
single-core devices. Bug 915733 [1] contains more information on this.

> If we want to do anything useful with the data it most likely needs to
> go to the parent process anyway. Child processes never have permission
> to directly write to files, and of course any UI that lives outside of
> the application is handled by other processes, which means that it has
> to at least go through the main process.

That doesn't need to be necessarily true; I remember a suggestion (from
Dave Hylands IIRC) that in a lot of cases we can delegate opening a file
(and the relevant permission checks) to the main process but then have
the file descriptor handed over to the child process for
reading/writing. This preserves our security model but removes most of
the overhead associated with IPC. I can't remember on which bug that
comment was made but it must have been related to bug 896810 [2]. As far
as logging goes this sounds like a workable solution for speeding up
logging in child processes.

Dave, I'm I remembering correctly or is my tired mind making things up?

 Gabriele

[1] Use Linux AIO instead of IO threads for IPC
https://bugzilla.mozilla.org/show_bug.cgi?id=915733
[2] (move-apis-to-child) Move more implementations out of parent process
https://bugzilla.mozilla.org/show_bug.cgi?id=896810



signature.asc
Description: OpenPGP digital signature
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Fabrice Desré]

On 08/28/2014 01:39 AM, Gabriele Svelto wrote:

> That doesn't need to be necessarily true; I remember a suggestion (from
> Dave Hylands IIRC) that in a lot of cases we can delegate opening a file
> (and the relevant permission checks) to the main process but then have
> the file descriptor handed over to the child process for
> reading/writing. This preserves our security model but removes most of
> the overhead associated with IPC. I can't remember on which bug that
> comment was made but it must have been related to bug 896810 [2]. As far
> as logging goes this sounds like a workable solution for speeding up
> logging in child processes.
> 
> Dave, I'm I remembering correctly or is my tired mind making things up?

The fd opening in parent then handing to the child is done to remote jar
openings for instance. But i'm not sure we can log directly from the
child process in all cases. For instance, anything that needs to be
available for devtools needs to go to the parent first.

Fabrice
-- 
Fabrice Desré
b2g team
Mozilla Corporation
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Jonas Sicking]

On Thu, Aug 28, 2014 at 1:39 AM, Gabriele Svelto  wrote:
> IPC is quite expensive in general on our implementation so even when
> it's non-blocking it does have a measurable performance impact on
> single-core devices. Bug 915733 [1] contains more information on this.

There's a lot of disagreement on this. So far no one has been able to
show a profile where this is the case. Every time that we have
performance with IPC it is because the parent process is busy doing
other things which means that it takes longer than we want to get a
response.

I.e. the problem is one of latency rather than throughput in every
profile that anyone has been able to produce.

However for logging we don't need to get any response. And it doesn't
matter if the logging message appears a few ms later than when the
logging call was made. So this is not a problem.

If you have a profile that can show otherwise, please do share.

/ Jonas
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Dave Hylands]

Even if we send the log to the parent, I'd still like to see the logcat happen 
in the child in the thread that originally issues the log. 

This accomplishes 2 things: 

1 - logcat records the PID and TID of the logger. I've found this to be 
extremely useful information which would be lost. in logcat if the logging is 
done in the parent. 

2 - If you do the logcat in the parent you get out-of-sequence logs. The 
parents logs will be logged with lower latency than the childs, which causes 
weird logs. When the child does the logging, the sequence is preserved. This is 
extremely useful when logging any type of activity which is split between the 
child and parent. 

Dave Hylands 

- Original Message -

> From: "Jonas Sicking" 
> To: "Gabriele Svelto" 
> Cc: "Eric Rahm" , mozilla-dev-...@lists.mozilla.org, "Dave
> Hylands" 
> Sent: Thursday, August 28, 2014 10:09:05 AM
> Subject: Re: [b2g] Log collection needs improvement

> On Thu, Aug 28, 2014 at 1:39 AM, Gabriele Svelto  wrote:
> > IPC is quite expensive in general on our implementation so even when
> > it's non-blocking it does have a measurable performance impact on
> > single-core devices. Bug 915733 [1] contains more information on this.

> There's a lot of disagreement on this. So far no one has been able to
> show a profile where this is the case. Every time that we have
> performance with IPC it is because the parent process is busy doing
> other things which means that it takes longer than we want to get a
> response.

> I.e. the problem is one of latency rather than throughput in every
> profile that anyone has been able to produce.

> However for logging we don't need to get any response. And it doesn't
> matter if the logging message appears a few ms later than when the
> logging call was made. So this is not a problem.

> If you have a profile that can show otherwise, please do share.

> / Jonas
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Tim Chien]

I want to second Dave's point here -- it's important if we could
preserve the order between processes so that we could work on Gaia
System bugs.

I also want to say if we could reflect the log level in Gecko, the
Console API have already design to have a set of levels:
https://developer.mozilla.org/en-US/docs/Web/API/console

- console.log
- console.info
- console.warn
- console.error

Not sure four level is enough though. It's probably make sense to
establish an agreement among Gaia developers on how to utilize these
functions (but first we should be allowed to use them).

On Fri, Aug 29, 2014 at 1:50 AM, Dave Hylands  wrote:
> Even if we send the log to the parent, I'd still like to see the logcat
> happen in the child in the thread that originally issues the log.
>
> This accomplishes 2 things:
>
> 1 - logcat records the PID and TID of the logger. I've found this to be
> extremely useful information which would be lost. in logcat if the logging
> is done in the parent.
>
> 2 - If you do the logcat in the parent you get out-of-sequence logs. The
> parents logs will be logged with lower latency than the childs, which causes
> weird logs. When the child does the logging, the sequence is preserved. This
> is extremely useful when logging any type of activity which is split between
> the child and parent.
>
> Dave Hylands
>
> 
>
> From: "Jonas Sicking" 
> To: "Gabriele Svelto" 
> Cc: "Eric Rahm" , mozilla-dev-...@lists.mozilla.org,
> "Dave Hylands" 
> Sent: Thursday, August 28, 2014 10:09:05 AM
>
> Subject: Re: [b2g] Log collection needs improvement
>
> On Thu, Aug 28, 2014 at 1:39 AM, Gabriele Svelto 
> wrote:
>> IPC is quite expensive in general on our implementation so even when
>> it's non-blocking it does have a measurable performance impact on
>> single-core devices. Bug 915733 [1] contains more information on this.
>
> There's a lot of disagreement on this. So far no one has been able to
> show a profile where this is the case. Every time that we have
> performance with IPC it is because the parent process is busy doing
> other things which means that it takes longer than we want to get a
> response.
>
> I.e. the problem is one of latency rather than throughput in every
> profile that anyone has been able to produce.
>
> However for logging we don't need to get any response. And it doesn't
> matter if the logging message appears a few ms later than when the
> logging call was made. So this is not a problem.
>
> If you have a profile that can show otherwise, please do share.
>
> / Jonas
>
>
>
> ___
> dev-b2g mailing list
> dev-b2g@lists.mozilla.org
> https://lists.mozilla.org/listinfo/dev-b2g
>



-- 
Tim Guan-tin Chien, Engineering Manager and Front-end Lead, Firefox
OS, Mozilla Corp. (Taiwan)
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Tim Chien]

Hi all,

I couldn't help but did some block box testing myself to measure the
speed of console.log().

I have put the result on
https://bugzilla.mozilla.org/show_bug.cgi?id=1066581

>From perspective of Gaia, I think we should be allow to use console
API methods once this bug is fixed.


On Fri, Aug 29, 2014 at 5:22 PM, Tim Chien  wrote:
> I want to second Dave's point here -- it's important if we could
> preserve the order between processes so that we could work on Gaia
> System bugs.
>
> I also want to say if we could reflect the log level in Gecko, the
> Console API have already design to have a set of levels:
> https://developer.mozilla.org/en-US/docs/Web/API/console
>
> - console.log
> - console.info
> - console.warn
> - console.error
>
> Not sure four level is enough though. It's probably make sense to
> establish an agreement among Gaia developers on how to utilize these
> functions (but first we should be allowed to use them).
>
> On Fri, Aug 29, 2014 at 1:50 AM, Dave Hylands  wrote:
>> Even if we send the log to the parent, I'd still like to see the logcat
>> happen in the child in the thread that originally issues the log.
>>
>> This accomplishes 2 things:
>>
>> 1 - logcat records the PID and TID of the logger. I've found this to be
>> extremely useful information which would be lost. in logcat if the logging
>> is done in the parent.
>>
>> 2 - If you do the logcat in the parent you get out-of-sequence logs. The
>> parents logs will be logged with lower latency than the childs, which causes
>> weird logs. When the child does the logging, the sequence is preserved. This
>> is extremely useful when logging any type of activity which is split between
>> the child and parent.
>>
>> Dave Hylands
>>
>> 
>>
>> From: "Jonas Sicking" 
>> To: "Gabriele Svelto" 
>> Cc: "Eric Rahm" , mozilla-dev-...@lists.mozilla.org,
>> "Dave Hylands" 
>> Sent: Thursday, August 28, 2014 10:09:05 AM
>>
>> Subject: Re: [b2g] Log collection needs improvement
>>
>> On Thu, Aug 28, 2014 at 1:39 AM, Gabriele Svelto 
>> wrote:
>>> IPC is quite expensive in general on our implementation so even when
>>> it's non-blocking it does have a measurable performance impact on
>>> single-core devices. Bug 915733 [1] contains more information on this.
>>
>> There's a lot of disagreement on this. So far no one has been able to
>> show a profile where this is the case. Every time that we have
>> performance with IPC it is because the parent process is busy doing
>> other things which means that it takes longer than we want to get a
>> response.
>>
>> I.e. the problem is one of latency rather than throughput in every
>> profile that anyone has been able to produce.
>>
>> However for logging we don't need to get any response. And it doesn't
>> matter if the logging message appears a few ms later than when the
>> logging call was made. So this is not a problem.
>>
>> If you have a profile that can show otherwise, please do share.
>>
>> / Jonas
>>
>>
>>
>> ___
>> dev-b2g mailing list
>> dev-b2g@lists.mozilla.org
>> https://lists.mozilla.org/listinfo/dev-b2g
>>
>
>
>
> --
> Tim Guan-tin Chien, Engineering Manager and Front-end Lead, Firefox
> OS, Mozilla Corp. (Taiwan)



-- 
Tim Guan-tin Chien, Engineering Manager and Front-end Lead, Firefox
OS, Mozilla Corp. (Taiwan)
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g

Re: [b2g] Log collection needs improvement

[Eric Rahm]

On 9/12/14 5:57 AM, Tim Chien wrote:

Hi all,

I couldn't help but did some block box testing myself to measure the
speed of console.log().

I have put the result on
https://bugzilla.mozilla.org/show_bug.cgi?id=1066581


From perspective of Gaia, I think we should be allow to use console

API methods once this bug is fixed.



Thanks for looking into this! So are you saying that the non-devtools 
numbers are good enough? If that's the case we probably don't even need 
to block on bug 1066581 and can recommend using console logging now.


For the non-devtools case I have confirmed that console messages are 
output to logcat and have a few bugs fixed/filed for enhancements:

  - Log category should be process name (instead of GeckoConsole) [1]
  - Log level should match the console method invoked (currently
everything is logged at the error level) [2]
  - console.error,assert,trace should include a stack trace [3]

-e

[1] https://bugzilla.mozilla.org/show_bug.cgi?id=1059593
[2] https://bugzilla.mozilla.org/show_bug.cgi?id=1060171
[3] https://bugzilla.mozilla.org/show_bug.cgi?id=1060161
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g