Welcome!

Welcome to the official BlackBerry Support Community Forums.

This is your resource to discuss support topics with your peers, and learn from each other.

inside custom component

Native Development

Reply
Developer
Developer
Posts: 174
Registered: ‎03-05-2009
My Device: Dev Alpha
My Carrier: -
Accepted Solution

understanding some log spamming (seems to be related to FPS)

Hi,

 

recently my log console (slog2info -w) seems to be spammed with the following recurring log message:

 

Oct 22 00:13:41.328 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default    255  FPS_WARNING: total frame time: 56 ms, event processing(1): 1 ms, render: 
54 ms, event processing(2): 0 ms, wait for GPU: 1 ms, #frames since last bad: 0
Oct 22 00:13:41.633 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default      0  LGM - RENDER_BEGIN  SINCE_LAST_RENDER_START: 360881704 ns
Oct 22 00:13:41.711 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default      0  LGM - RENDER_END  RENDER_DURATION: 78538229 ns TOTAL_FRAMES: 2505 FRAMES_
DROPPED: 1955
Oct 22 00:13:41.711 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default    255  FPS_WARNING: total frame time: 78 ms, event processing(1): 0 ms, render: 
77 ms, event processing(2): 1 ms, wait for GPU: 0 ms, #frames since last bad: 0
Oct 22 00:13:41.722 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default      0  LGM - RENDER_BEGIN  SINCE_LAST_RENDER_START: 89479344 ns
Oct 22 00:13:41.806 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default      0  LGM - RENDER_END  RENDER_DURATION: 83597609 ns TOTAL_FRAMES: 2506 FRAMES_
DROPPED: 1956
Oct 22 00:13:41.806 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default    255  FPS_WARNING: total frame time: 83 ms, event processing(1): 2 ms, render: 
80 ms, event processing(2): 0 ms, wait for GPU: 1 ms, #frames since last bad: 0
Oct 22 00:13:42.072 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default      0  LGM - RENDER_BEGIN  SINCE_LAST_RENDER_START: 350154714 ns
Oct 22 00:13:42.136 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default      0  NavigatorEventHandler::Received - BPS - NAVIGATOR_WINDOW_INACTIVE
Oct 22 00:13:42.136 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default      0  NavigatorEventHandler::Received - BPS - NAVIGATOR_WINDOW_COVER_ENTER
Oct 22 00:13:42.149 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default      0  LGM - RENDER_END  RENDER_DURATION: 77000000 ns TOTAL_FRAMES: 2507 FRAMES_
DROPPED: 1957
Oct 22 00:13:42.149 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default    255  FPS_WARNING: total frame time: 77 ms, event processing(1): 0 ms, render: 
74 ms, event processing(2): 3 ms, wait for GPU: 0 ms, #frames since last bad: 0
Oct 22 00:13:42.158 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default      0  LGM - RENDER_BEGIN  SINCE_LAST_RENDER_START: 86303191 ns
Oct 22 00:13:42.199 com.example.TestApp.testDev_teo_TestApp2e540a75.445038782              default      0  LGM - RENDER_END  RENDER_DURATION: 40356766 ns TOTAL_FRAMES: 2508 FRAMES_
DROPPED: 1958

 

anyone has any idea where this log message may be coming from? Or what could be causing this spamming (a few times per second) ??

 

Highlighted
Developer
Posts: 6,473
Registered: ‎12-08-2010
My Device: PlayBook, Z10
My Carrier: none

Re: understanding some log spamming (seems to be related to FPS)

[ Edited ]

I think we all get that sort of thing, and just ignore it.

My technique for ignoring involves using "grep" or "sed" to filter out the unwanted lines.

Here's what I've put into a script in my ~ folder after adding it to the PATH when I log in via SSH.

In ~/bin/slog, which is made executable with "chmod +x ~/bin/slog":  (note this is all on one line, with no spaces between the [^.] and the (.*), just in case your browser wraps it)

 

#!/bin/sh

slog2info -w | sed -re '/    default/d;s/^.{7}(\S+) ([^.]+\.[^.]+\.[^.]+)\.\S+\s+(\S+)\s+(.*)/\1 \2 \3 \4/'

With that, I just type "slog" every time I log in, and get "clean" output that looks something like this, and which excludes all those lines with "   default" in them:

08:47:11.411 com.example.bb10samples 0 -----ONLINE-----
08:47:11.411 com.example.bb10samples qt-msg* 0  RenderEngineManager::RenderEngineManager
08:47:11.436 com.example.bb10samples 0 -----ONLINE-----
08:47:11.522 com.example.bb10samples qt-msg 0  OrientationSupportPrivate::initDirectionAndOrientation:
   isCardOrViewer:  false
   displayOrientation: DeviceNorth
   uiOrientation: Portrait
   displayDirection: North
   nativeDisplayOrientation: Portrait
08:47:14.653 com.example.bb10samples qt-msg 0  file:///apps/com.example.bb10samples.geo.locationdiagnostics.testDev_diagnosticsc8041425/native/assets//LocationPage.qml:220: TypeError: Result of expression 'session' [undefined] is not an object.
08:47:21.788 com.example.bb10samples qt-msg 0  START 1 SystemSound::play
08:47:21.791 com.example.bb10samples qt-msg 0  START 1 SystemSoundPrivate::SystemSoundPrivate
08:47:21.793 com.example.bb10samples qt-msg 0  => END 1 ( 2 ms):
08:47:21.794 com.example.bb10samples qt-msg 0  START 1 SystemSoundPrivate::play
08:47:21.794 com.example.bb10samples qt-msg 0  SystemSoundPrivate::play: sound=8
08:47:21.795 com.example.bb10samples qt-msg 0  START 1 SystemSoundPrivate::send
08:47:21.795 com.example.bb10samples qt-msg 0  SystemSoundPrivate::send: sound=8, msg="

The benefit is the lines are much shorter, much of the "system" stuff is excluded, and I still get more than just the "qt-msg" lines in cases where I've registered other slog2 buffer names.

 

A much simpler approach is just to use "slog2info -w | grep qt-msg" but I found that inadequate.


Peter Hansen -- (BB10 and dev-related blog posts at http://peterhansen.ca.)
Author of White Noise and Battery Guru for BB10 and for PlayBook | Get more from your battery!
Developer
Developer
Posts: 174
Registered: ‎03-05-2009
My Device: Dev Alpha
My Carrier: -

Re: understanding some log spamming (seems to be related to FPS)

Thanks Peter...gonna give this a try today!. 

But regarding the log spamming, i was able to identify what was causing this. Having an active WebView control will spam your logs with the above messages (several times per second).

Developer
Posts: 6,473
Registered: ‎12-08-2010
My Device: PlayBook, Z10
My Carrier: none

Re: understanding some log spamming (seems to be related to FPS)

There are likely many causes. I have several apps without WebView controls, and just captured this from a quick launch of one of them (app id removed):

Oct 22 14:42:09.910 ca.engenuity.xxxx.18104350              default      0  LGM - RENDER_BEGIN  SINCE_LAST_RENDER_START: 229065076 ns
Oct 22 14:42:09.985 ca.engenuity.xxxx.18104350              default      0  LGM - RENDER_END  RENDER_DURATION: 75162845 ns TOTAL_FRAMES: 17 FRAMES_DROPPED: 8
Oct 22 14:42:09.985 ca.engenuity.xxxx.18104350              default    255  FPS_WARNING: total frame time: 75 ms, event processing(1): 0 ms, render: 75 ms, event processing(2): 0 ms, wait for GPU: 0 ms, #frames since last bad: 0

 


Peter Hansen -- (BB10 and dev-related blog posts at http://peterhansen.ca.)
Author of White Noise and Battery Guru for BB10 and for PlayBook | Get more from your battery!
Developer
Developer
Posts: 174
Registered: ‎03-05-2009
My Device: Dev Alpha
My Carrier: -

Re: understanding some log spamming (seems to be related to FPS)

but is it really spamming your console? like around 3-5 times the message per second?

 

i do see these messages every time i load a new control but it nevers spams like when a WebView control is active!

Developer
Posts: 6,473
Registered: ‎12-08-2010
My Device: PlayBook, Z10
My Carrier: none

Re: understanding some log spamming (seems to be related to FPS)

In the particular app I was reporting that from, it's not nearly that bad. I've seen it enough in various apps (maybe when scrolling a ListView or something, I don't recall) that it was a key reason my "sed" filter eliminates anything tagged "default", even at the risk of removing the odd useful entry from the system. Sounds like WebView's a real bad culprit for that though.

Peter Hansen -- (BB10 and dev-related blog posts at http://peterhansen.ca.)
Author of White Noise and Battery Guru for BB10 and for PlayBook | Get more from your battery!