Strange Startup SlowDown()

Monkey Targets Forums/Android/Strange Startup SlowDown()

Midimaster(Posted 2013) [#1]
I did some test with accelerating startup procedure of android apps and I detected some strange behaviors:

I tested loading a first image and nothing else:

timing results:
E/        (22403): Creating OpenGL 1.1 Session
I/[Monkey](22403): V04  call OnCreate() after 310msec
I/[Monkey](22403):   OnCreate() finished after 367msec
I/[Monkey](22403): First OnRender() after 369msec
I/[Monkey](22403): First DrawImage() after 374msec
I/[Monkey](22403): First DrawImage() after 634msec
I/[Monkey](22403): First DrawImage() after 812msec
I/[Monkey](22403): First DrawImage() after 825msec
I/[Monkey](22403): First DrawImage() after 844msec


the image was visible after 812msec for the first time. The attempts before were only calls without results. It was as expected.





No I added 8kB datas with SaveState(). The next following start was like this:

timing results:
E/        (21939): Creating OpenGL 1.1 Session
I/[Monkey](21939): V02  call OnCreate() after 509msec
I/[Monkey](21939):   LoadState() successful after 629msec
I/[Monkey](21939):   OnCreate() finished after 640msec
I/[Monkey](21939): First OnRender() after 642msec
I/[Monkey](21939): First DrawImage() after 643msec
I/[Monkey](21939): First DrawImage() after 1106msec
I/[Monkey](21939): First DrawImage() after 1597msec
I/[Monkey](21939): First DrawImage() after 1612msec


A check inside OnCreate already reads values of the LoadState() after 629msec successfully. Ok... But the first stabil DrawImage was now after 1597msec!!! 800msec later!!! Why?





Last Test: very strange:

Now I comment out the LoadState(), but it was still there:

timing results:
E/        (21708): Creating OpenGL 1.1 Session
I/[Monkey](21708): V02  call OnCreate() after 457msec
I/[Monkey](21708):   without LoadState() after 583msec
I/[Monkey](21708):   OnCreate() finished after 585msec
I/[Monkey](21708): First OnRender() after 587msec
I/[Monkey](21708): First DrawImage() after 596msec
I/[Monkey](21708): First DrawImage() after 1047msec
I/[Monkey](21708): First DrawImage() after 1479msec
I/[Monkey](21708): First DrawImage() after 1497msec
I/[Monkey](21708): First DrawImage() after 1513msec


also the same bad timing!!!


This is the test code:

Strict
Import mojo

Class Game Extends App

	Field Timer%, AnfangRenderZeit%, LoadedState$
	Field Logo:Image
	
	Method OnCreate%()
		Print "V04  call OnCreate() after " + Millisecs() + "msec"
		SetUpdateRate 60
		Logo=LoadImage("LogoLeer.png")
		'LoadedState=LoadState()
		'If LoadedState.Contains("!")
		'	Print "  LoadState() successful after " + Millisecs() + "msec"
		'Else
		'	Print "  without LoadState() after " + Millisecs() + "msec"		
		'Endif	
		Print "  OnCreate() finished after " + Millisecs() + "msec"
		Return 0
	End	

	Method OnUpdate%()
		If KeyHit(KEY_ESCAPE) Then 
			Local a$=""
			For Local i%=0 To 8000
			'	a=a+"!"
			Next
			'SaveState a
			Error ""
		Endif
		Return 0
	End	

	Method OnRender%()
		If AnfangRenderZeit=0
				AnfangRenderZeit=Millisecs()
				Print "First OnRender() after " + Millisecs() + "msec"
		Endif
			SetColor 255,255,255
			DrawImage Logo,0,0
				Print "First DrawImage() after " + Millisecs() + "msec"
		Return 0
	End	
	
End

Function Main%()
	New Game
	Return 0
End



Nobuyuki(Posted 2013) [#2]
Did you run DDMS with the allocation tracker to see if LoadState() and your subsequent parsing was manipulating a lot of strings? String utilization is often a source of slowdown on the Android target -- they are immutable, and from my understanding, string manipulation and the de/allocation of strings can cause slowdowns and eventually GC invokes.


Midimaster(Posted 2013) [#3]
as you see in the code sample, there is not a single string manipulation on the LoadState() content. I do not use LoadState()! The content is yet not loaded! It is only "still there" from a prior start...


AdamRedwoods(Posted 2013) [#4]
Millisecs() - oldMillisecs
is a bit clearer to me.

this
I/[Monkey](21708): First DrawImage() after 596msec
I/[Monkey](21708): First DrawImage() after 1047msec
I/[Monkey](21708): First DrawImage() after 1479msec
I/[Monkey](21708): First DrawImage() after 1497msec
I/[Monkey](21708): First DrawImage() after 1513msec

becomes:
1047-596=451ms
1479-1047=432ms
1497-1479=18ms
1513-1497=16ms


so i think the reason for the slow initial draws is that java vm is:
1. loading textures into video memory
2. analyzing the loop and making optimizations