Track and Report times of each EntitySystem.update() if requested

[Barryrowe]

This PR provides code to time each system's update() call and report that back after each Engine.updateDebug() tick. Outside of adding 1 if() check, does not alter the existing Engine.update() method.

[dsaltares]

Thanks for the PR. However, why not simply use a profiler? I don't think we need this to be part of Ashley itself.

[Barryrowe]

Do you have any suggestions of tools for profiling while running on a mobile device? Hopefully that's a good answer and this can be left out. The issue we're running into is that our slowdowns aren't reproducible on anything but our test mobile devices.

How would you feel about something like below instead, that would allow consumers to "hook into" and apply our own timing, or any other logic:

//This is a terrible name, for the interface
public interface ISystemUpdateWrapper {
//Only pass in the class so we don't encourage manipulation of the system itself mid update tick
beforeSystemUpdate(Class <? extends EntitySystem> systemClass); 
afterSystemUpdate(Class <? extends EntitySystem> systemClass);
}

//Engine could then have something like:
public class Engine{
 ...
 setSystemUpdateWrapper(ISystemUpdateWrapper wrapper){
 this.systemUpdateWrapper = wrapper;
 }

 ...
 update(float delta){
 ...
  if(this.systemUpdateWrapper == null){
    //normal Update      
  }else{
     foreach system
     this.wrapper.beforeSystemUpdate(system.getClass());
      //normal update
     this.wrapper.afterSystemUpdate(system.getClass());      
  }
}

I thought about creating a set of "Timed**System" base classes that individually take in a "timekeeper" and wrap their own update and force implementation of timedUpdate(), but that felt pretty fragile, and would need an implementation for each base system (Iterating, Interval, etc.).

[dsaltares]

The issue we're running into is that our slowdowns aren't reproducible on anything but our test mobile devices.

Okay, so profiling the desktop application is not an option here. I don't know about device profilers although I'm sure there are some.

If the slowdown is only noticeable on mobile it could very well be due to garbage collection. Make sure you're using pooling and don't make allocation of temporary objects on the stack mid loop.

Still, let's say we want to measure the time each system takes so you guys can focus on optimising the biggest offenders on mobile.

Why not have something like below?

public class UpdateProfiler {
    private final Updater updater;

    public UpdateProfiler(Updater updater) {
        this.updater = updater;
    }

    public long update(float deltaTime) {
        long start = System.currentTimeMilis();
        updater.update(deltaTime);
        long end = System.currentTimeMilis();

        return end - start;
    }

    public interface Updater {
        public void update(float deltaTime);
    }   
}

public class SomeSystem extends EntitySystem {
    private final UpdateProfiler updateProfiler;

    public SomeSystem() {
        updateProfiler = new UpdateProfiler(new SomeSystemUpdater());
    }

    public void update(float deltaTime) {
        long time = updateProfiler.update(deltaTime);
        // do whatever with the time
    }

    private void profiledUpdate(float deltaTime) {
        // Logic goes here
        // If this is an IteratingSystem, you can call super.update(deltaTime) here
    }

    private class SomeSystemUpdater implements Updater {
        public void update(float deltaTime) {
            profiledUpdate(deltaTime);
        }
    }
}

Wouldn't this be a lot less intrusive? You could publish the results using the Signal system and they'd be picked up by the StatisticsManager.

What do you think?

[Barryrowe]

Thanks for the tips. I'll double check and make sure everything is pooled, and look for any uninitialized temp values.(I bet there are some offending vectors, there's always at least one :) )

The example you provided is close to what I started to implement in my project. I had 2 issues with that approach.

1. Consumers have to implement the boilerplate UpdateProfiler -> UpdaterImpl code for at least all of the baseClass types of systems being implemented or created, and Remember to add it for any new system types in the future that don't extend the existing Inheritance structure.
2. It also has the downside of requiring any existing systems to be modified to override profiledUpdate instead of update (assuming we setup the Profiler in the base class). Which makes timing any 3rd party systems a matter of extending them with your own "profiled" versions rather than just plugging in a global profiler.

If I'm mistaken on either of these 2 points let me know. If there's a way I'm not seeing to implement your suggestion above transparently for existing systems without modifying them, that's the way to go for sure.

I can definitely see, and I now agree with, the argument that timing of systems isn't the job of Ashley. However, if it doesn't kill the benchmarks, it seems providing a pluggable hook around system updates could be beneficial for developers.

I could see a TimerProfiler and an EntityChurnProfiler(tracks entityCounts added/removed during each system) being useful, and would love to include them in a set of Ashley extensions I've been working on.

[dsaltares]

What about a generic wrapper class instead?

public class ProfiledSystem<T extends EntitySystem> extends EntitySystem {
    private final EntitySystem system;
    private long lastUpdateTime = 0L;

    public ProfiledSystem(T system) {
        this.system = system;
    }

    public void update(float deltaTime) {
        long start = System.currentTimeMillis();
        system.update(deltaTime);
        long end = System.currentTimeMillis();
        lastUpdateTime = end - start;
    }

    public long getLastUpdateTime() {
        return lastUpdateTime;
    }
}

You can then do:

private class SystemA extends EntitySystem {
    public void update(float deltaTime) {
        try {
            Thread.sleep(1L);
        } catch (InterruptedException e) {

        }
    }
}

@Test
public void profiledSystemTest () {
    Engine engine = new Engine();
    ProfiledSystem<SystemA> system = new ProfiledSystem<SystemA>(new SystemA());

    engine.addSystem(system);
    engine.update(0.0f);
    assertTrue(system.getLastUpdateTime() > 0L);
}

The constructor ends up being a bit verbose but it's not invasive at all, there's no boilerplate and no need to modify your existing entity systems.

[Barryrowe]

I'm going to spend some time with this today and see if I can find a good way to easily turn this "on/off" for all the systems without swapping out the constructors directly.

The SystemManager would need to be updated here though to allow profiling of multiple Profiled systems. Since SystemManager.addClass calls system.getClass() to determine the, if we wrap all the systems, they'll all be seen as "ProfiledSystem", and end up removing the system added just before them.

Unit Test for this situation:

public class ProfiledSystemTest {

    private class SystemA extends EntitySystem {
        public void update(float deltaTime) {
            try {
                Thread.sleep(1L);
            } catch (InterruptedException e) {

            }
        }
    }

    private class SystemB extends EntitySystem {
        public void update(float deltaTime) {
            try {
                Thread.sleep(2L);
            } catch (InterruptedException e) {

            }
        }
    }

    @Test
    public void profiledSystemTest () {
        Engine engine = new Engine();
        ProfiledSystem<SystemA> system = new ProfiledSystem<SystemA>(new SystemA());

        engine.addSystem(system);
        engine.update(0.0f);

        Assert.assertTrue(system.getLastUpdateTime() > 0L);
    }

    @Test
    public void engineSupportsMultipleProfiledSystemsTest () {
        Engine engine = new Engine();
        ProfiledSystem<SystemA> systemA = new ProfiledSystem<SystemA>(new SystemA());
        ProfiledSystem<SystemB> systemB = new ProfiledSystem<SystemB>(new SystemB());

        engine.addSystem(systemA);
        engine.addSystem(systemB);
        engine.update(0.0f);

        Assert.assertEquals("Engine should have 2 registered Systems", engine.getSystems().size());
        Assert.assertTrue("SystemA should have been run and be greater than 0L", systemA.getLastUpdateTime() > 0L);
        Assert.assertTrue("SystemB should have been run and be greater than 1L", systemB.getLastUpdateTime() > 1L);

    }
}

[dsaltares]

See what @junkdog proposed on #216. I like the idea.

[Barryrowe]

I like that idea. It feels pretty similar to the ISystemUpdateWrapper concept I was playing with above, but with an implementation in Artemis to review.

I see some complications with the implementation right now, but I've only started wrapping my head around it. I'm going to try and implement it and see if I can get something generic and flexible without exposing too much of the engine details to consumers of the new API.

If we can come up with a way to ensure the lines below get called inBetween each system update without requiring implementations of the SystemInvocationStrategy to do so directly I think it's exactly what we want.

Lines 184-185 of Engine.java

    componentOperationHandler.processOperations();
    entityManager.processPendingOperations();

[lukz]

@Barryrowe did you figured out a way to get it working?

[Barryrowe]

Sorry @lukz I got caught up in another project and haven't gotten back to this. Still on my backlog, but it hasn't taken priority yet.