Meta Employee

Odd spikes after updating

5 replies
1294 views

Hello!

I just updated my old old build from Unity 5.1.0 (SDK 0.6...) to 5.3.0f4 (latest tools) and I am getting a huge performance loss.

Unity v5.3.0f4, Oculus Utilities v0.1.3.0, OVRPlugin v0.1.4.0.

I know I know this is not that weird for what I have read, but look at this screenshot running the profiler directly from my Note 4(4.4.4):

http://i.imgur.com/kugl6et.png

I disabled all renderers and pretty much anything that could overhead the CPU and GPU (it's basically renderingh just a skybox) and still I get 14ms in CPU with regular 30ms spikes.

Maybe I did the upgrade very wrong? :S This was working before at 55fps (with everything enabled of course)

HALP!

Edit: oj just seen this viewtopic.php?f=37&t=27963#p310144 but he is at least rendering stuff. Should I downgrade again? what is the previous recommended version?

This topic has been closed for replies.

cybereality

Inspiring

Is you profile for the phone or for running in the Editor on the PC? Is your PC capable and have you installed the latest drivers? If the issue is on the phone, can you provide a logcat? You can also try Unity 5.2.3p3.

LucaMefistoAuthor

Meta Employee

Thanks for the reply cybereality!

-The profiler is for the phone indeed (Galaxy note 4) running in the profiling mode.
My computer is quite powerful (drivers updated 2 weeks ago maximum, GTX970 )
I will extract a log cat and put it here when I get home (around 3-4 hours) and also try 5.2.3p3

LucaMefistoAuthor

Meta Employee

The logcat keeps spamming this:



I/E:\tw\33a21edae6c0e9ad\Software\OculusSDK\Integrations\Unity\Releases\0(11727): OVR_TW_SetDebugMode(0,0)

I/E:\tw\33a21edae6c0e9ad\Software\OculusSDK\Integrations\Unity\Releases\0(11727): OVR_TW_SetDebugMode(0,0)

I/E:\tw\33a21edae6c0e9ad\Software\OculusSDK\Integrations\Unity\Releases\0(11727): OVR_TW_SetDebugMode(0,0)

I/E:\tw\33a21edae6c0e9ad\Software\OculusSDK\Integrations\Unity\Releases\0(11727): OVR_TW_SetDebugMode(0,0)

I/E:\tw\33a21edae6c0e9ad\Software\OculusSDK\Integrations\Unity\Releases\0(11727): OVR_TW_SetDebugMode(0,0)

I/E:\tw\33a21edae6c0e9ad\Software\OculusSDK\Integrations\Unity\Releases\0(11727): OVR_TW_SetDebugMode(0,0)

I/E:\tw\33a21edae6c0e9ad\Software\OculusSDK\Integrations\Unity\Releases\0(11727): OVR_TW_SetDebugMode(0,0)

I/E:\tw\33a21edae6c0e9ad\Software\OculusSDK\Integrations\Unity\Releases\0(11727): OVR_TW_SetDebugMode(0,0)

I/E:\tw\33a21edae6c0e9ad\Software\OculusSDK\Integrations\Unity\Releases\0(11727): OVR_TW_SetDebugMode(0,0)

I/E:\tw\33a21edae6c0e9ad\Software\OculusSDK\Integrations\Unity\Releases\0(11727): OVR_TW_SetDebugMode(0,0)

Could be the cause?

Edit: I got rid of that log (positional tracking was enabled) but the spikes persist. This is my "cleaner" logcat




D/NetworkStatsFactory(  918): UpdateStatsForKnox

V/NetworkStats(  918): performPollLocked(flags=0x1)

D/ConnectivityService(  918): getLinkProperties for 1000{LinkAddresses: []  Routes: [] DnsAddresses: [] Domains: nullMTU: 0}

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

V/NetworkStats(  918): performPollLocked() took 44ms

I/OVR     (12307): DeviceManagerThread - poll(fds,1,1000) = 0 (Tid=12426)

I/VrApi   (12307): FPS=53,Prd=44ms,Tear=0,Early=1,Stale=10,VSnc=1,Lat=1,CPU0/GPU=2/2,1497/389MHz,TA=F/F/F/F,Free=995MB,PLS=0,Temp=22.3C

E/LocSvc_api_v02( 9670): D/locClientQmiCtrlPointInit:1924]: Service not up. Starting delay timer

W/TimeWarp(12307): V-sync 5397: Eye 0, CPU latency 0.001, GPU latency 0.008, Total latency = 0.009

I/TimeWarp(12307): WarpSwap: usleep( 395 )

I/TimeWarp(12307): WarpSwap: usleep( 374 )

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

I/TimeWarp(12307): WarpSwap: usleep( 400 )

W/TimeWarp(12307): V-sync 5411: Eye 0, CPU latency 0.001, GPU latency 0.008, Total latency = 0.009

D/BatteryService(  918): level:100, scale:100, status:5, health:2, present:true, voltage: 4257, temperature: 223, technology: Li-ion, AC powered:false, USB powered:true, Wireless powered:false, icon:17303785, invalid charger:0, online:4, current avg:-549, charge type:1, power sharing:false, high voltage charger:false, capacity:322000

D/BatteryService(  918): Sending ACTION_BATTERY_CHANGED.

D/KeyguardUpdateMonitor( 1179): received broadcast android.intent.action.BATTERY_CHANGED

D/KeyguardUpdateMonitor( 1179): handleBatteryUpdate

D/UiModeManager(  918): mCoverManager.getCoverState() : true

D/STATUSBAR-PhoneStatusBar( 1200):  mBrightnessEnablebySettings = true mBrightnessEnablebyBattery = true mBrightnessEnablebyDisableFlag = true mPmsBrightnessEnablebySettings = true

D/BatteryMeterView( 1200): ACTION_BATTERY_CHANGED : level:100 status:5 health:2

I/TimeWarp(12307): WarpSwap: usleep( 635 )

W/TimeWarp(12307): V-sync 5420: Eye 0, CPU latency 0.001, GPU latency 0.009, Total latency = 0.010

I/TimeWarp(12307): WarpSwap: usleep( 196 )

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

I/OVR     (12307): DeviceManagerThread - poll(fds,1,1000) = 0 (Tid=12426)

I/VrApi   (12307): FPS=54,Prd=44ms,Tear=1,Early=0,Stale=9,VSnc=1,Lat=1,CPU0/GPU=2/2,1497/389MHz,TA=F/F/F/F,Free=995MB,PLS=0,Temp=22.3C

I/TimeWarp(12307): WarpSwap: usleep( 91 )

V/AlarmManager(  918): waitForAlarm result :8

V/AlarmManager(  918): ClockReceiver onReceive() ACTION_TIME_TICK

D/KeyguardUpdateMonitor( 1179): received broadcast android.intent.action.TIME_TICK

D/KeyguardUpdateMonitor( 1179): handleTimeUpdate

D/accuweather( 2740): [KK AccuPhone]>>> WCS:142 [0:0] action : androidintentactionTIME_TICK

D/accuweather( 2740): [KK AccuPhone]>>> UIM:119 [0:0] getInstance

D/accuweather( 2740): [KK AccuPhone]>>> UIM:286 [0:0] direct update clock

D/accuweather( 2740): [KK AccuPhone]>>> RU:74 [0:0] get ww = 339, wh = 160span x = 4, span y = 2

D/accuweather( 2740): [KK AccuPhone]>>> UIM:1428 [0:0] mc sy = 2

D/accuweather( 2740): [KK AccuPhone]>>> RU:74 [0:0] get ww = 339, wh = 160span x = 4, span y = 2

D/accuweather( 2740): [KK AccuPhone]>>> UIM:189 [0:0] get widget 4x2 view!!! wid = 1

E/accuweather( 2740): [KK AccuPhone]>>> UIM:1466 [0:0] bTM 20 20

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

E/Watchdog(  918): !@Sync 2971

W/TimeWarp(12307): V-sync 5472: Eye 0, CPU latency 0.001, GPU latency 0.008, Total latency = 0.009

I/TimeWarp(12307): WarpSwap: usleep( 66 )

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

I/OVR     (12307): DeviceManagerThread - poll(fds,1,1000) = 0 (Tid=12426)

I/VrApi   (12307): FPS=55,Prd=44ms,Tear=3,Early=0,Stale=8,VSnc=1,Lat=1,CPU0/GPU=2/2,1497/389MHz,TA=F/F/F/F,Free=995MB,PLS=0,Temp=22.3C

W/TimeWarp(12307): V-sync 5521: Eye 0, CPU latency 0.001, GPU latency 0.009, Total latency = 0.010

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

W/TimeWarp(12307): V-sync 5524: Eye 0, CPU latency 0.000, GPU latency 0.009, Total latency = 0.010

I/TimeWarp(12307): preFinish - afterSleepTime = 5.9 ms

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

V/NetworkStats(  918): performPollLocked(flags=0x1)

D/NetworkStatsFactory(  918): UpdateStatsForKnox

D/ConnectivityService(  918): getLinkProperties for 1000{LinkAddresses: []  Routes: [] DnsAddresses: [] Domains: nullMTU: 0}

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

V/NetworkStats(  918): performPollLocked() took 53ms

I/TimeWarp(12307): WarpSwap: usleep( 87 )

W/TimeWarp(12307): V-sync 5541: Eye 0, CPU latency 0.001, GPU latency 0.009, Total latency = 0.009

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

I/OVR     (12307): DeviceManagerThread - poll(fds,1,1000) = 0 (Tid=12426)

I/VrApi   (12307): FPS=57,Prd=44ms,Tear=1,Early=0,Stale=6,VSnc=1,Lat=1,CPU0/GPU=2/2,1497/389MHz,TA=F/F/F/F,Free=995MB,PLS=0,Temp=22.3C

D/ConnectivityManager(30671): getActiveNetworkInfo : NetworkInfo: type: WIFI[], state: CONNECTED/CONNECTED, reason: (unspecified), extra: "NukeTheWhales", roaming: false, failover: false, isAvailable: true, isConnectedToProvisioningNetwork: false

W/TimeWarp(12307): V-sync 5581: Eye 0, CPU latency 0.001, GPU latency 0.010, Total latency = 0.011

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

I/TimeWarp(12307): WarpSwap: usleep( 642 )

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

I/OVR     (12307): DeviceManagerThread - poll(fds,1,1000) = 0 (Tid=12426)

I/VrApi   (12307): FPS=54,Prd=44ms,Tear=3,Early=1,Stale=9,VSnc=1,Lat=1,CPU0/GPU=2/2,1497/389MHz,TA=F/F/F/F,Free=995MB,PLS=0,Temp=22.3C

E/LocSvc_api_v02( 9670): D/locClientQmiCtrlPointInit:1924]: Service not up. Starting delay timer

W/TimeWarp(12307): V-sync 5631: Eye 0, CPU latency 0.001, GPU latency 0.010, Total latency = 0.010

I/TimeWarp(12307): WarpSwap: usleep( 9 )

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

I/TimeWarp(12307): WarpSwap: usleep( 918 )

W/TimeWarp(12307): V-sync 5649: Eye 0, CPU latency 0.001, GPU latency 0.010, Total latency = 0.011

I/TimeWarp(12307): WarpSwap: usleep( 291 )

W/TimeWarp(12307): V-sync 5657: Eye 0, CPU latency 0.001, GPU latency 0.009, Total latency = 0.009

I/TimeWarp(12307): WarpSwap: usleep( 418 )

W/TimeWarp(12307): V-sync 5659: Eye 0, CPU latency 0.001, GPU latency 0.009, Total latency = 0.009

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

D/NetworkStatsFactory(  918): UpdateStatsForKnox

V/NetworkStats(  918): performPollLocked(flags=0x1)

D/ConnectivityService(  918): getLinkProperties for 1000{LinkAddresses: []  Routes: [] DnsAddresses: [] Domains: nullMTU: 0}

I/OVR     (12307): DeviceManagerThread - poll(fds,1,1000) = 0 (Tid=12426)

I/VrApi   (12307): FPS=56,Prd=44ms,Tear=1,Early=0,Stale=6,VSnc=1,Lat=1,CPU0/GPU=2/2,1497/389MHz,TA=F/F/F/F,Free=995MB,PLS=0,Temp=22.3C

I/TimeWarp(12307): WarpSwap: usleep( 425 )

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

V/NetworkStats(  918): performPollLocked() took 45ms

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

W/TimeWarp(12307): V-sync 5703: Eye 0, CPU latency 0.001, GPU latency 0.009, Total latency = 0.010

I/TimeWarp(12307): WarpSwap: usleep( 195 )

W/TimeWarp(12307): V-sync 5704: Eye 0, CPU latency 0.000, GPU latency 0.008, Total latency = 0.009

I/TimeWarp(12307): WarpSwap: usleep( 23 )

I/TimeWarp(12307): WarpSwap: usleep( 247 )

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

I/OVR     (12307): DeviceManagerThread - poll(fds,1,1000) = 0 (Tid=12426)

I/VrApi   (12307): FPS=53,Prd=44ms,Tear=4,Early=1,Stale=13,VSnc=1,Lat=1,CPU0/GPU=2/2,1497/389MHz,TA=F/F/F/F,Free=995MB,PLS=0,Temp=22.3C

I/TimeWarp(12307): preFinish - afterSleepTime = 5.0 ms

W/TimeWarp(12307): V-sync 5757: Eye 0, CPU latency 0.005, GPU latency 0.007, Total latency = 0.012

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

I/OVR     (12307): DeviceManagerThread - poll(fds,1,1000) = 0 (Tid=12426)

I/VrApi   (12307): FPS=56,Prd=44ms,Tear=2,Early=0,Stale=8,VSnc=1,Lat=1,CPU0/GPU=2/2,1497/389MHz,TA=F/F/F/F,Free=995MB,PLS=0,Temp=22.3C

W/TimeWarp(12307): V-sync 5809: Eye 0, CPU latency 0.001, GPU latency 0.010, Total latency = 0.011

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

I/TimeWarp(12307): WarpSwap: usleep( 469 )

W/TimeWarp(12307): V-sync 5824: Eye 0, CPU latency 0.001, GPU latency 0.009, Total latency = 0.010

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

D/NetworkStatsFactory(  918): UpdateStatsForKnox

V/NetworkStats(  918): performPollLocked(flags=0x1)

D/ConnectivityService(  918): getLinkProperties for 1000{LinkAddresses: []  Routes: [] DnsAddresses: [] Domains: nullMTU: 0}

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

D/NtpTrustedTime(  918): currentTimeMillis() cache hit

V/NetworkStats(  918): performPollLocked() took 41ms

I/TimeWarp(12307): WarpSwap: usleep( 297 )

E/csd_client(  331): csd_service_init: Check modem power up with MDM reset !!!

I/OVR     (12307): DeviceManagerThread - poll(fds,1,1000) = 0 (Tid=12426)

It states 53 fps sometimes in there (which is very little for something rendering just a skybox...) I imagine on the peaks will be lower (searching...)

Edit2: Downgrading to 5.2.3p3 did not seem to work. I will spend some time this weekend with this maybe recreating the same scene in a brand new project... :cry:

vrdaveb

Inspiring

Do you get the same spikes when you run the OVR/Scenes/Room.unity scene?

LucaMefistoAuthor

Meta Employee

Updating to 5.3.1 seems to have them gone!

I also noticed that my Oclusion Culling bake was maybe overcomplex, probably affecting this?

Get Help

Sign up

Login with SSO

Login to the community

Login with SSO