Thursday, August 6, 2015

Fixing SKLabelNode performance issues

I'm loving working with the Sprite Kit API for game development.  Using all the tools I'm effective with, that other software dev folks would know: a good code editor, nice tool chain and a well-documented API; I can really get stuff done.

In a primarily graphical environment sure you can lay things out visually, but for the thing I'm currently trying to do - layout a virtual keyboard for a game - I need to do it programmatically so I can cope with changes in screen size.

But: I found some issues with the layout code pausing big time, during the load sequence.  This was revealed by testing on a 3 year old iPad Mini that I keep around just because its great at exposing these sorts of problems.

Folks, do not EVER rely on testing your game or app in the simulator.  Use a device ALWAYS.  Once you have your project mostly done and discover you've introduced some horrible performance issue, its going to be impossible to find.

This one manifested as an ugly lag in the response after hitting the "Play" button and it needed to be fixed.  I used the Xcode tool "Instruments" and fired up the Time Profiler to drill and find the culprit.  If you've never used Time Profiler before there's a good Ray Wenderlich tutorial on it.  I also used a home grown time logging tool, the code for which I have stuck up on GitHub.  Being able to instrument my code by hand is a great complement to using the Instruments tool.  Here's some of the output from my tool:

Time stamps:
    Before press play button - 0.0
    Play button pressed - 0.00773762501194142
    Starting transition - 0.322784499992849
    Game Scene didMoveToView start - 0.323094458348351
    Scheduled music - 0.323781083337963
    setupGamePlay: done setupCarousel - 0.329451166675426
    setupGamePlay: done setupMonsters - 0.678052625007695
    setupGamePlay: done setupMissile - 0.945051541668363
    setupGamePlay: done targetMissileAt - 0.94512124999892
    Setup Gameplay - 0.945148375001736
    About to create keyboard - 1.07598399999551
    addKeys: About to calculateKeyCapMetrics - 1.07624216665863
    About to create SKLabelNode - 1.07625199999893
    About to set label text - 1.07641391665675
    About to set font size - 4.5479717499984
    About to set font color - 4.55641954168095
    Done with label - 4.55644533334998
    calculateKeyCapMetrics: about to setup frame - 4.56316420834628
    calculateKeyCapMetrics: about to calculate frame - 4.60020420834189

    calculateKeyCapMetrics: done - 4.60023920834647

There's a 3-4 second delay there while the SKLabel's text is set! That's crazy!

Luckily that is a one off, and subsequent calls to set the text with the same font turn out to be fast. Very interesting. More investigation with the Time Profiler:


It reveals that the iOS True Type font system is having to load the font - its a custom one that I added to the project, not one that ships with iOS. Its during the first load and unpacking all the font information that the delay is incurred. I guess there might be some reading from flash of the iOS device in that as well.

Right: so that makes it a good candidate for pre-loading after the start scene has been displayed but before the player presses the start button.

So, off I got and implement pre-loading of the font.
    
    func preloadResources() {
        let label = SKLabelNode(fontNamed: "Ancona-Ex")
        label.text = "preload"
    }

    
    override func update(currentTime: NSTimeInterval)
    {
        if !preload
        {
            preloadResources()
        }
    }

With that done, time to run a new profile session:

Time stamps:
    Before press play button - 0.0
    Play button pressed - 0.00989962500170805
    Starting transition - 0.318517291656462
    Game Scene didMoveToView start - 0.318650125002023
    Scheduled music - 0.318978958326625
    setupGamePlay: done setupCarousel - 0.324560000008205
    setupGamePlay: done setupMonsters - 0.69843762498931
    setupGamePlay: done setupMissile - 0.969889125000918
    setupGamePlay: done targetMissileAt - 0.969957374996739
    Setup Gameplay - 0.969982250011526
    About to create keyboard - 1.11275391667732
    addKeys: About to calculateKeyCapMetrics - 1.11366166666267
    About to create SKLabelNode - 1.11367308333865
    About to set label text - 1.11383529167506
    About to set font size - 1.11686108334106
    About to set font color - 1.12038704167935
    Done with label - 1.1204140833288
    calculateKeyCapMetrics: about to setup frame - 1.12638933333801
    calculateKeyCapMetrics: about to calculate frame - 1.1502004583308

    calculateKeyCapMetrics: done - 1.15022912499262

Time to create the label text has now dropped away to nothing! Nice.

Hope that helps someone else working with SKLabelNode and custom fonts.