Slow resume, need help speeding it up

Started by zammbi, May 23, 2012, 07:04:46 AM

Previous topic - Next topic
Print
Go Down Pages1
User actions

zammbi

May 23, 2012, 07:04:46 AM Last Edit: May 23, 2012, 07:11:17 AM by zammbi
I'm trying to speed up resuming of a 3d world, something near the speeds of our iPhone version if possible.
Basically the 3d world is in an activity and I need to resume that activity as fast as possible.

Any other optimisations I try in code causes JPCT to crash. So looking for some suggestions.

Here is the basics of my code:
Code Select
@Override
    protected void onCreate(final Bundle savedInstanceState) {

        synchronized (InputWorld3dActivity.masterLock) {
            if (InputWorld3dActivity.inputInstance != null) {
                ReflectionHelper.copy(InputWorld3dActivity.inputInstance, this,1); //Copies all activity data across to this one.
                if (this != InputWorld3dActivity.inputInstance) {
                    InputWorld3dActivity.inputInstance.finish();
                }
            }
            InputWorld3dActivity.inputInstance = this;
        }
        super.onCreate(savedInstanceState);
        setContentView(R.layout.wwlayout);
        boolean isOpenGl2 = false;

        mGLView = (GLSurfaceView) findViewById(R.id.glsurfaceview);

        PhoneRank.printPhoneStats();

        if (PhoneRank.isSafeForOpenGL2WithAA(this)) {
            try {
                if (GraphicsHelper.turnOnOpenGL2(mGLView)) {
                    final AAConfigChooser aa;
                    if (PhoneRank.getMaxAndFreeMemRank() == MemRank.VERY_HIGH) {// Most likely a top phone.
                        aa = new AAConfigChooser(mGLView, true);
                        Log.d("WW", "Turning on AA with transparency.");
                    } else {
                        aa = new AAConfigChooser(mGLView);
                        Log.d("WW", "Turning on AA without transparency.");
                    }
                    mGLView.setEGLConfigChooser(aa);

                    isOpenGl2 = true;
                    Log.d("WW", "Using OpenGL 2.0");
                }
            } catch (final Exception e) {
                //No OpenGL2 support.
                e.printStackTrace();
            }
        }

        if (!isOpenGl2) {
            Log.d("WW", "Using OpenGL 1.1");
            mGLView.setEGLConfigChooser(new EGLOpenGL1Chooser());
        }

        if (renderer == null) {
            renderer = new World3dBase(); //World3dBase is the GLSurfaceView.Renderer
        }
        renderer.setOpenGl2(isOpenGl2);

        mGLView.setRenderer(renderer);
}


Here are the current logs:

Quote05-23 16:46:25.135: INFO/ActivityManager(202): START {cmp=nz.co.nuffie.android.crichq/.threedimensional.InputWorld3dActivity (has extras)} from pid 15374
05-23 16:46:25.244: DEBUG/dalvikvm(202): GC_FOR_ALLOC freed 538K, 13% free 22056K/25223K, paused 79ms
05-23 16:46:25.260: INFO/Database(15374): Saved over to database, total time taken: 7 ms.
05-23 16:46:25.275: DEBUG/nz.co.nuffie.android.crichq.threedimensional.InputWorld3dActivity(15374): Copying data from object.
05-23 16:46:25.275: INFO/jPCT-AE(15374): onCreate
05-23 16:46:25.283: DEBUG/PhoneRank(15374): Max mem:128 Mem Left:124 Allocated:4 Free Mem:2 CPU cores free:2
05-23 16:46:25.291: DEBUG/PhoneRank(15374): Max Mem: 128 Mem Left:124
05-23 16:46:25.291: DEBUG/PhoneRank(15374): Very high ram free.
05-23 16:46:25.291: DEBUG/WW(15374): Turning on AA with transparency.
05-23 16:46:25.291: DEBUG/WW(15374): Using OpenGL 2.0
05-23 16:46:25.299: VERBOSE/PhoneStatusBar(282): setLightsOn(true)
05-23 16:46:25.299: DEBUG/PhoneStatusBar(282): showing the MENU button
05-23 16:46:25.361: INFO/jPCT-AE(15374): MSAA enabled with 2 samples!
05-23 16:46:25.361: INFO/jPCT-AE(15374): Unable to find a matching config...using default!
05-23 16:46:25.369: INFO/ActivityManager(202): Displayed nz.co.nuffie.android.crichq/.threedimensional.InputWorld3dActivity: +107ms
05-23 16:46:25.424: INFO/jPCT-AE(15374): Visibility lists disposed!
05-23 16:46:25.424: INFO/jPCT-AE(15374): All texture data unloaded from gpu!
05-23 16:46:25.424: INFO/jPCT-AE(15374): Disposing VBOs!
05-23 16:46:25.424: INFO/jPCT-AE(15374): Renderer disposed!
05-23 16:46:25.424: INFO/jPCT-AE(15374): Initializing GL20 render pipeline...
05-23 16:46:25.424: INFO/jPCT-AE(15374): Loading default shaders !
05-23 16:46:25.424: INFO/jPCT-AE(15374): 0 shaders in replacement map!
05-23 16:46:25.424: INFO/jPCT-AE(15374): Default fragment shader is: /defaultFragmentShader.src
05-23 16:46:25.424: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.432: INFO/jPCT-AE(15374): Text file from InputStream loaded...2008 bytes
05-23 16:46:25.432: INFO/jPCT-AE(15374): Default vertex shader is: /defaultVertexShader.src
05-23 16:46:25.432: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.432: INFO/jPCT-AE(15374): Text file from InputStream loaded...3897 bytes
05-23 16:46:25.432: INFO/jPCT-AE(15374): Compiling shader program!
05-23 16:46:25.432: INFO/jPCT-AE(15374): Handles of 210003: 4/36
05-23 16:46:25.432: INFO/jPCT-AE(15374): Loading default shaders (Tex0)!
05-23 16:46:25.432: INFO/jPCT-AE(15374): 0 shaders in replacement map!
05-23 16:46:25.432: INFO/jPCT-AE(15374): Default fragment shader is: /defaultFragmentShader.src
05-23 16:46:25.440: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.440: INFO/jPCT-AE(15374): Text file from InputStream loaded...201 bytes
05-23 16:46:25.440: INFO/jPCT-AE(15374): Default vertex shader is: /defaultVertexShader.src
05-23 16:46:25.440: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.455: INFO/jPCT-AE(15374): Text file from InputStream loaded...3421 bytes
05-23 16:46:25.455: INFO/jPCT-AE(15374): Compiling shader program!
05-23 16:46:25.455: INFO/jPCT-AE(15374): Handles of 420006: 1/33
05-23 16:46:25.455: INFO/jPCT-AE(15374): Loading default shaders (Tex1)!
05-23 16:46:25.455: INFO/jPCT-AE(15374): 0 shaders in replacement map!
05-23 16:46:25.455: INFO/jPCT-AE(15374): Default fragment shader is: /defaultFragmentShader.src
05-23 16:46:25.463: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.463: INFO/jPCT-AE(15374): Text file from InputStream loaded...871 bytes
05-23 16:46:25.463: INFO/jPCT-AE(15374): Default vertex shader is: /defaultVertexShader.src
05-23 16:46:25.463: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.463: INFO/jPCT-AE(15374): Text file from InputStream loaded...3791 bytes
05-23 16:46:25.463: INFO/jPCT-AE(15374): Compiling shader program!
05-23 16:46:25.471: INFO/jPCT-AE(15374): Handles of 630009: 2/36
05-23 16:46:25.471: INFO/jPCT-AE(15374): Loading default shaders (Tex0Light0)!
05-23 16:46:25.471: INFO/jPCT-AE(15374): 0 shaders in replacement map!
05-23 16:46:25.471: INFO/jPCT-AE(15374): Default fragment shader is: /defaultFragmentShader.src
05-23 16:46:25.471: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.471: INFO/jPCT-AE(15374): Text file from InputStream loaded...201 bytes
05-23 16:46:25.471: INFO/jPCT-AE(15374): Default vertex shader is: /defaultVertexShader.src
05-23 16:46:25.471: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.479: INFO/jPCT-AE(15374): Text file from InputStream loaded...1200 bytes
05-23 16:46:25.479: INFO/jPCT-AE(15374): Compiling shader program!
05-23 16:46:25.479: INFO/jPCT-AE(15374): Handles of 840012: 1/10
05-23 16:46:25.479: INFO/jPCT-AE(15374): Loading default shaders (Fog)!
05-23 16:46:25.479: INFO/jPCT-AE(15374): 0 shaders in replacement map!
05-23 16:46:25.479: INFO/jPCT-AE(15374): Default fragment shader is: /defaultFragmentShader.src
05-23 16:46:25.479: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.494: DEBUG/dalvikvm(15374): GC_CONCURRENT freed 10078K, 29% free 31389K/43975K, paused 2ms+4ms
05-23 16:46:25.494: INFO/jPCT-AE(15374): Text file from InputStream loaded...328 bytes
05-23 16:46:25.494: INFO/jPCT-AE(15374): Default vertex shader is: /defaultVertexShader.src
05-23 16:46:25.494: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.494: INFO/jPCT-AE(15374): Text file from InputStream loaded...3668 bytes
05-23 16:46:25.494: INFO/jPCT-AE(15374): Compiling shader program!
05-23 16:46:25.494: INFO/jPCT-AE(15374): Handles of 1050015: 1/36
05-23 16:46:25.494: INFO/jPCT-AE(15374): Loading default shaders (FogLight0)!
05-23 16:46:25.494: INFO/jPCT-AE(15374): 0 shaders in replacement map!
05-23 16:46:25.494: INFO/jPCT-AE(15374): Default fragment shader is: /defaultFragmentShader.src
05-23 16:46:25.494: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.494: INFO/jPCT-AE(15374): Text file from InputStream loaded...328 bytes
05-23 16:46:25.494: INFO/jPCT-AE(15374): Default vertex shader is: /defaultVertexShader.src
05-23 16:46:25.494: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.494: INFO/jPCT-AE(15374): Text file from InputStream loaded...1516 bytes
05-23 16:46:25.494: INFO/jPCT-AE(15374): Compiling shader program!
05-23 16:46:25.494: INFO/jPCT-AE(15374): Handles of 1260018: 1/14
05-23 16:46:25.494: INFO/jPCT-AE(15374): Loading default shaders (Tex0Amb)!
05-23 16:46:25.494: INFO/jPCT-AE(15374): 0 shaders in replacement map!
05-23 16:46:25.494: INFO/jPCT-AE(15374): Default fragment shader is: /defaultFragmentShader.src
05-23 16:46:25.502: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.502: INFO/jPCT-AE(15374): Text file from InputStream loaded...199 bytes
05-23 16:46:25.502: INFO/jPCT-AE(15374): Default vertex shader is: /defaultVertexShader.src
05-23 16:46:25.502: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.502: INFO/jPCT-AE(15374): Text file from InputStream loaded...757 bytes
05-23 16:46:25.502: INFO/jPCT-AE(15374): Compiling shader program!
05-23 16:46:25.518: INFO/jPCT-AE(15374): Handles of 1470021: 1/5
05-23 16:46:25.518: INFO/jPCT-AE(15374): Loading default shaders (Depth)!
05-23 16:46:25.518: INFO/jPCT-AE(15374): 0 shaders in replacement map!
05-23 16:46:25.518: INFO/jPCT-AE(15374): Default fragment shader is: /defaultFragmentShader.src
05-23 16:46:25.518: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.518: INFO/jPCT-AE(15374): Text file from InputStream loaded...745 bytes
05-23 16:46:25.518: INFO/jPCT-AE(15374): Default vertex shader is: /defaultVertexShader.src
05-23 16:46:25.518: INFO/jPCT-AE(15374): Loading file from InputStream
05-23 16:46:25.518: INFO/jPCT-AE(15374): Text file from InputStream loaded...248 bytes
05-23 16:46:25.518: INFO/jPCT-AE(15374): Compiling shader program!
05-23 16:46:25.525: INFO/jPCT-AE(15374): Handles of 1680024: 1/1
05-23 16:46:25.525: INFO/jPCT-AE(15374): GL20 render pipeline initialized!
05-23 16:46:25.525: INFO/jPCT-AE(15374): OpenGL vendor:     Imagination Technologies
05-23 16:46:25.525: INFO/jPCT-AE(15374): OpenGL renderer:   PowerVR SGX 540
05-23 16:46:25.525: INFO/jPCT-AE(15374): OpenGL version:    OpenGL ES 2.0 build 1.8@785978
05-23 16:46:25.525: INFO/jPCT-AE(15374): OpenGL renderer initialized (using 2 texture stages)
05-23 16:46:25.525: INFO/jPCT-AE(15374): 23fps
05-23 16:46:25.525: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:25.525: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:25.549: DEBUG/dalvikvm(15374): GC_FOR_ALLOC freed 197K, 29% free 31386K/43975K, paused 24ms
05-23 16:46:25.557: INFO/dalvikvm-heap(15374): Grow heap (frag case) to 34.740MB for 4194320-byte allocation
05-23 16:46:25.588: DEBUG/dalvikvm(15374): GC_CONCURRENT freed 3K, 20% free 35478K/43975K, paused 1ms+3ms
05-23 16:46:25.611: DEBUG/dalvikvm(15374): GC_FOR_ALLOC freed 0K, 20% free 35478K/43975K, paused 23ms
05-23 16:46:25.619: INFO/dalvikvm-heap(15374): Grow heap (frag case) to 38.737MB for 4194320-byte allocation
05-23 16:46:26.041: DEBUG/dalvikvm(15374): GC_FOR_ALLOC freed 0K, 11% free 39574K/43975K, paused 23ms
05-23 16:46:26.494: DEBUG/dalvikvm(15374): GC_FOR_ALLOC freed <1K, 8% free 40599K/43975K, paused 23ms
05-23 16:46:26.650: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:26.650: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:26.729: DEBUG/dalvikvm(15374): GC_FOR_ALLOC freed 10925K, 29% free 31383K/43975K, paused 23ms
05-23 16:46:26.729: INFO/dalvikvm-heap(15374): Grow heap (frag case) to 34.737MB for 4194320-byte allocation
05-23 16:46:26.752: DEBUG/dalvikvm(15374): GC_FOR_ALLOC freed 0K, 20% free 35479K/43975K, paused 23ms
05-23 16:46:26.775: DEBUG/dalvikvm(15374): GC_FOR_ALLOC freed 0K, 20% free 35479K/43975K, paused 22ms
05-23 16:46:26.775: INFO/dalvikvm-heap(15374): Grow heap (frag case) to 38.737MB for 4194320-byte allocation
05-23 16:46:26.822: DEBUG/dalvikvm(15374): GC_CONCURRENT freed 0K, 11% free 39575K/43975K, paused 2ms+4ms
05-23 16:46:27.244: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.244: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.307: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.307: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.307: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.307: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.307: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.307: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.307: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.315: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.315: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.315: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.315: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.315: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.315: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.315: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.315: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.315: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.315: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.315: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.330: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.330: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.338: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.338: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.338: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.338: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.338: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.338: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.338: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.338: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.338: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.338: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.338: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.338: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.338: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.338: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.338: INFO/jPCT-AE(15374): OpenGL context has changed(2)...recovering for renderer 1/0!
05-23 16:46:27.338: INFO/jPCT-AE(15374): Creating buffers...
05-23 16:46:27.338: INFO/jPCT-AE(15374): Compiling shader program!
05-23 16:46:27.338: INFO/jPCT-AE(15374): Handles of 1890027: 0/2
05-23 16:46:27.346: DEBUG/3d(15374): Change camera view to: BOTH
05-23 16:46:27.377: INFO/jPCT-AE(15374): 1fps
05-23 16:46:28.393: INFO/jPCT-AE(15374): 31fps
05-23 16:46:29.408: INFO/jPCT-AE(15374): 30fps
05-23 16:46:30.424: INFO/jPCT-AE(15374): 30fps
05-23 16:46:31.440: INFO/jPCT-AE(15374): 30fps

Looks like getting stuck on "OpenGL context has changed(2)...recovering for renderer 1/0!" and shader compiling.

EgonOlsen

#1
May 23, 2012, 04:43:20 PM
All these operations have to be done if the context changes and the speed in which they are executed depends on how fast the cpu/gpu can handle them. I don't see room for improvement here. You can try to disable VBOs. That should make these "creating buffers" operations go away, but it might be slower (usually, it isn't though). But apart from that, it takes 2 seconds to reinitialize things. Is this really a problem?

zammbi

#2
May 23, 2012, 11:33:24 PM Last Edit: May 24, 2012, 12:19:02 AM by zammbi
QuoteYou can try to disable VBOs. That should make these "creating buffers" operations go away, but it might be slower (usually, it isn't though)
Seemed to have helped thanks.

QuoteBut apart from that, it takes 2 seconds to reinitialize things. Is this really a problem?
This is on my Galaxy Nexus. Which is a lot quicker than all our other devices. But yes this is actually a major problem for us.
I'm currently working on input for wagon wheel and pitch map, each thing happens very fast in cricket and therefore we need to allow fast input. Even with the Galaxy Nexus it is still slow.

Is there any extra caching you can do? Force keeping things on the graphs chip or in memory? Black magic?

Edit:
I found that turning off OpenGL 2.0 on the med/lower phones helped with there slowness problem. It seems its the shader loading that slowing things down. However I want to keep OpenGL 2.0 on if possible for AA. Is there any optimisations/caching you can do there?

EgonOlsen

#3
May 24, 2012, 08:18:44 AM
Nope, i can't cache anything there. Loading the source files isn't an issue. It's the compilation that takes its time and there's no way around this. It's speed solely depends on the speed of the shader compiler in the driver and you can't feed precompiled shader code like you can in desktop GL.
However, you can try a hack...
The default shaders are part of the jar. You can unzip the jar and replace all shaders that aren't used in your application with more or less empty vertex and fragment shaders (you might have to fiddle around with the attributes and uniforms...i'm not 100% sure if the engine expects some of them to be there in all cases). That should reduce compilation time of these shaders (i'm not sure by which amount though...). Detecting which shaders are actually used is a trial and error process. You can derive their purposes roughly from the name...

zammbi

#4
May 24, 2012, 11:03:32 AM
QuoteHowever, you can try a hack...
Thanks for the help. That does sounds a little annoying heh.

What about OES_get_program_binary support?  ;D
http://stackoverflow.com/questions/8718574/how-to-speed-up-shader-loading-compiling-on-android

EgonOlsen

#5
May 24, 2012, 09:07:36 PM
I wasn't aware of this extension, because everything i always read said, that support for shaders is GLSL only...i'll look into it.

EgonOlsen

#6
May 24, 2012, 09:22:16 PM
I can't find any support for this in the Java SDK. The NDK seems to have it though, but that's not worth much in this case. The SDK allows to upload shaders in binary format, but i can't find a way to get the binary from the driver...and that would be needed.

zammbi

#7
May 24, 2012, 11:43:24 PM
Bugger I can't find anything else either. I'll try asking on Stackoverflow.
Print
Go Up Pages1
User actions